Skip to content

Contact payment latency on staging with the shared Paykit runtime: pin paykit-rs#171 and re-measure #868

Open

Description

@jvsena42

Follow-up from #856. With the shared Paykit runtime on paykit rc59, contact-payment actions are much slower against the staging homeserver than on master. The remaining cost is the per-transaction homeserver lock in the SDK, which pubky/paykit-rs#171 targets. This issue tracks pinning a paykit release that contains #171 and re-measuring.

Measured on staging at #856 head c334a6f (iOS simulator, with an Android emulator as the linked contact):

Action c334a6f master
Send Request → "Sent" 80 s 6–9 s
Contact payments off 6 min 45 s seconds
Request or Pay offered after cold launch ≤ ~4 min immediate
paykit_session loaded from keychain flat ~48/min, idle included —

Done when, on staging, Send Request reaches "Sent" within ~10 s, contact payments off completes within ~30 s, and Request or Pay is offered within one maintenance round (~60 s) of a cold launch.

Journey to reproduce

<journey name="Contact Payment Latency">
  <description>
    Measures how long contact-payment actions take against the staging homeserver. Requires two Bitkit instances saved as each other's contacts and linked as identities, with contact payments on, both on the staging homeserver.
  </description>
  <actions>
    <action>Force-quit Bitkit on device A, launch it, and note the launch time</action>
    <action>Every 2 minutes, open the contact for device B from Contacts and tap Pay (id "ContactPay"); record the first time the Request or Pay sheet (id "RequestOrPaySheet") appears instead of the amount screen, and verify it is within 60 seconds of launch</action>
    <action>Tap Request, enter 1,000 sats, tap Send Request and record the time until "Payment requested" (id "PaymentRequestSent") appears; verify it is within 10 seconds</action>
    <action>On device B, idle on Home, record when the Payment Request confirmation screen (id "PaymentRequestConfirm") appears</action>
    <action>On device A, open Settings, General, turn off Enable payments with contacts (id "ContactPaymentsToggle") and record the time until the switch is enabled again showing off; verify it is within 30 seconds and no error toast appears</action>
    <action>Turn Enable payments with contacts back on and record the time until it settles on</action>
  </actions>
</journey>

Activity

  1. ben-kaufman commented on Oct 3, 2026

    @ben-kaufman
    Contributor

    Retested with published rc60 on iOS 10b85a1 and Android dc73b29d7, using fresh staging identities saved as contacts on both devices.

    • Warm iOS Contact Pay showed Request or Pay in under a second.
    • A 1,000-sat request was sent and appeared in Android’s request list. Send Request was still busy after 26.7 seconds and was complete at the next check, 93.3 seconds after tapping. This is a measured interval, not an exact latency, and still misses the 10-second target.
    • iOS sharing OFF immediately disabled local publication, but remote cleanup exceeded 30 seconds. Both private/public cleanup flags eventually cleared. Android withdrawal also completed with both cleanup flags cleared.
    • Initial linking still took minutes. This was fresh setup, not the cold-launch journey, and does not validate the 61-contact case.

    rc60 includes #169/#170/#171, so the release dependency is removed, but this performance issue is not resolved. The remaining active send/withdrawal paths still perform multiple serialized shared-state transactions. Separating their network time from app-queue and lock waits is the next step; these results do not establish that the homeserver itself is the bottleneck. No payment was broadcast in this run.

  2. ben-kaufman commented on Oct 3, 2026

    @ben-kaufman
    Contributor

    Latest staging measurements used the published rc61 binaries with one linked, unfunded iOS/Android pair:

    • Warm iOS Request or Pay opened in under one second.
    • A 5,000-sat request sent at approximately 15:23:20 UTC completed between 23.2 and 25.6 seconds after Send.
    • Android's open request list was still missing it at 4.9 minutes and showed the matching request by 6.4 minutes. This is the observed display interval, not an exact network-delivery timestamp.
    • Android's private withdrawal phase took about 49 seconds in an earlier rc61 run. That is not the full public/private cleanup duration.

    Both PRs now use published rc62. It retains the batching and polling improvements and fixes a separate SDK issue where four concurrent outbound peers could consume each other's leases while waiting on shared storage. It does not explain or establish a fix for the one-peer delay above. No rc62 staging latency result is claimed here.

    Keep this open. We need timings for repository/SDK queue waits, outbound work, intake and request-list updates before attributing the remaining delay to Bitkit or the homeserver. Android also queues overlapping refreshes instead of coalescing them as iOS does; its impact in this run is unmeasured. No safety timeout was reduced.

    No payment was broadcast in these unfunded-wallet runs. Full payment/unlock, the 61-contact case, cold start and backup-stall QA remain unverified. The separate wallet broadcast dependency is still tracked in iOS #844 and Android #1384.

  3. jvsena42 commented on Oct 4, 2026

    @jvsena42
    MemberAuthor

    Re-measured on staging at #856 head 134dce1 (Paykit rc62, which includes paykit-rs#171). Two iOS simulators, fresh identities.

    Action rc62 (134dce1) rc59 (c334a6f) Target
    Send Request → "Sent" 33–58 s and ~100 s 80 s ≤ ~10 s
    Request presented on the receiver 2 min 43 s and 4 min 48 s ~11.5 min —
    Contact payments off ~110 s 6 min 45 s ≤ ~30 s
    Contact payments on 29–47 s 53 s —
    Request or Pay after cold launch 3 min 21 s (clean run) ≤ ~4 min ≤ ~60 s
    First link, fresh pair ~4 min 40 s to 5 min ~10.5 min —
    Paying a request, swipe → success ~70 s (payee received) — —
    paykit_session loaded from keychain, idle ~37–40/min ~48/min —

    rc62 is faster on most rows, and nothing fails: no lease-expired lines and no crash. Every target is still missed, so this stays open.

    Where the time goes now:

    • A Contact Pay tap that doesn't get Request or Pay spins for 50–100 s before falling back to the amount screen.
    • A cold launch takes 39–98 s to restore the Paykit session, behind concurrent_update init failures.
  4. ben-kaufman commented on Oct 5, 2026

    @ben-kaufman
    Contributor

    I profiled one linked, unfunded staging pair using a local build of #171 at 13feb12a. These measurements predate the later registry/endpoint lock reuse and the newest iOS cleanup changes; they are not measurements of the currently published rc62 or the final PR head.

    Sending one request took 22.416s:

    • Dispatch and queue wait: 0.295s.
    • Identity check: 0.848s.
    • Link-state read: 0.848s.
    • Other local/dispatch time: 0.446s.
    • Save proposal: 4.679s.
    • Process outbound: 15.300s.

    A second request took 21.169s. Both appeared on Android, but Android restarted during the test, so this does not establish warm delivery latency.

    Sharing OFF switched the UI immediately, but the last remote cleanup call completed after 84.326s:

    Work Seconds
    Dispatch and initial peer lookup 1.038
    Batched private withdrawal 21.079
    Drain, checks and interleaved poll/backup work 21.408
    Private capability registry update 12.748
    Queue wait 1.694
    Public endpoint cleanup 13.292
    Queue wait 2.836
    Final registry update 10.233

    The drain included an unnecessary 11.296s link check, now skipped when nothing remains queued. Sharing ON also repeated a registry update unnecessarily; that is removed. The channel-availability refresh no longer starts another public publication alongside its explicit publication.

    These are wrapper execution times, including SDK checks, not isolated network/CPU timings. Warm Request or Pay opened within one second, but remote actions remain too slow. The newer direct SDK measurements show further improvement, not a completed mobile retest. Keeping this open; no funded payment or content unlock was tested.

  5. ben-kaufman commented on Oct 5, 2026

    @ben-kaufman
    Contributor

    Retested with current #171 source, not published rc62: measured breakdown. Request sending took 24.0s; sharing OFF remote work took 63.1s, with both cleanup flags clearing afterward. The main phases are listed there. These still miss the targets, so this remains open. No funded payment or content unlock was tested.

  6. jvsena42 commented on Oct 5, 2026

    @jvsena42
    MemberAuthor

    Numbers at #856 e2b7326 (rc62), two simulators on staging, linked pair:

    Flow Measured
    Cold launch → session restored 20 s and 98 s
    Cold launch → Request or Pay offered ≤ 2 min 41 s and 4 min 53 s
    Send Request → "Sent" 57–77 s and 146–173 s
    Bell Pay tap → confirm screen 118.7 s, no progress shown
    Swipe → broadcast 86 s
    Sharing OFF / ON settles 89–113 s / 28–34 s
    Relaunch 55 s after sharing ON → session restored 6 min 13 s (shared_state_busy ×3)

    Until the session restores, the bell, contact names in activity, the Contacts screen and bitkit://contact deeplinks are all unavailable.

  7. ben-kaufman commented on Oct 5, 2026

    @ben-kaufman
    Contributor

    New same-identity staging measurements with the FFI batching fix: request send 21.6s -> 16.6s; full sharing withdrawal 68.2s -> 46.4s. Warm Contact Pay was 10.2s, almost entirely SDK execution in that sample. The local toggle changes immediately; withdrawal numbers include remote cleanup. Detailed queue owners, storage counts and limitations are in pubky/paykit-rs#171 (comment) . These are individual unfunded runs, not final-head acceptance: the latest recovery-marker fix still needs device retesting. Keeping this open.

  8. ben-kaufman commented on Oct 5, 2026

    @ben-kaufman
    Contributor

    Matched before/after measurements with the current iOS source and the SDK batching changes: warm Pay 8.5s to 5.0s; send request 18.2s to 14.6s; incoming preparation 20.4s to 20.9s; full sharing withdrawal 44.7s to 40.2s. Both withdrawals finished with cleanup flags clear.

    Incoming preparation still spends about 20s inside the SDK, not waiting for the app queue or wallet. Withdrawal spends about 34s in the SDK and 6s waiting for other SDK operations. Those paths still need work, so this issue remains open. One contact, one ordered comparison, unfunded wallets; no full payment claim. The staged-handshake follow-up is not included yet.

    Combined results and scope: pubky/paykit-rs#171 (comment)

  9. ben-kaufman commented on Oct 6, 2026

    @ben-kaufman
    Contributor

    I repeated the flows with the existing Send sheet and local builds of the combined SDK stack. The known request details appear immediately and the swipe stays loading until preparation is complete; the sheet then becomes payable in place.

    The SDK preparation fell from 16.8s to 7.6s, but the actual incoming-sheet wait was still 17.9s versus 17.3s. The candidate spent 9.4s behind a private-list publication that the same polling round started before presenting the request. I am fixing that scheduling order without interrupting active writes.

    Warm Contact Pay was 4.5s, sending a request 19.8s, and complete sharing withdrawal 43.2s. Those are single samples, not averages. No payment was broadcast. Full comparison and limitations. This issue stays open.

  10. ben-kaufman commented on Oct 6, 2026

    @ben-kaufman
    Contributor

    Retested the same identity pair with the latest app changes and the unreleased #171 SDK build. Incoming request preparation fell from 18.3s to 5.0s, and the existing Send sheet shows the request details with payment disabled/loading until ready. Send Request took 13.6s; warm Contact Pay took 5.9s; full sharing withdrawal still took 44.8s.

    Sender tap to receiver-ready was about 24s, including sending and inbox scheduling. These are single measured runs, not averages or full payment completion. Withdrawal and larger-contact performance remain open. The app PR still uses published rc62.

    Full paired results and timing breakdown.

  11. ben-kaufman commented on Oct 6, 2026

    @ben-kaufman
    Contributor

    The latest measured builds use the production SDK source in rc63, with tracing enabled. Full timings and limitations.

    • Contact Pay: iOS amount sheet in 8.6s, repeat 6.2s. Android Send visible 4.5s after handler start.
    • Send Request: about 15s on both platforms.
    • Received request: Pay enabled about 3.5-3.7s after preparation/presentation starts. Detection and polling add another 10-21s in these samples.
    • Sharing OFF: 64.5s iOS and 41.2s Android, including 20.3s and 6.5s of queue wait respectively.
    • Fresh linking is still slow. Both apps eventually reached Linked, with iOS observed Linked by 117s after Save. The first iOS private Pay attempt failed preparation before a later attempt opened its private endpoint in 2.8s.

    Performance remains open. These are individual runs, not matched before/after measurements or downloaded-rc63 binary tests. There was no funded payment in this capture. Large-contact mobile tests and Bitkit plus a running Server still need validation. No five-minute pending-write wait occurred in these completed samples.

  12. jvsena42 commented on Oct 6, 2026

    @jvsena42
    MemberAuthor

    Numbers at #856 591ac12 with paykit rc63, two simulators on staging, fresh identities:

    Action rc63 rc62 Target
    Send Request → "Sent" ≤ 13–17 s ≤ ~30 s, 57–173 s ~10 s
    Request reaches the receiver (sheet opens) 17.5–27 s after the Send tap 43–59 s n/a
    Automatic sheet preparing → ready 3.3 s, 15.5 s 57–60 s 3 s
    Bell Pay tap → ready 15.6 s 36.7 s 3 s
    Swipe → broadcast ~33–36 s ~54 s n/a
    Contact payments off / on 26–46 s / ≤ 20 s 89–113 s / 28–34 s ~30 s
    Cold launch → session restored 11–12 s; 61 s once right after a sharing change 19.6–117 s; up to 6 min 13 s n/a
    Cold launch → Request and Pay offered 35 s – 2 min 21 s (bracket) up to 4 min 53 s ~60 s
    First link, fresh pair ≤ 3 min 3 s ~7 min n/a

    Close to target now: Send Request and contact payments off. Still above: Pay → ready when the wallet has to build the transaction (15.6 s), swipe → broadcast, the time until Request is offered after a launch or a new link, and the one 61 s restore with two concurrent_update lines after a sharing change.

  13. jvsena42 commented on Oct 6, 2026

    @jvsena42
    MemberAuthor

    Numbers at #856 f79cfcb with paykit rc65 (two simulators, staging, identities carried over from rc63): payment and sharing timings are unchanged from rc63 (Send Request ≤ 14 s, sheet ready 3.5 s, swipe → broadcast 34–42 s, sharing off 25–43 s). Paying a contact whose sharing is off now shows the "Unable To Pay Contact" toast in ≤ 4 s.

    Open on rc65: a cold launch shortly after a write is slow. A quiet launch restores in ~12 s. A launch 38 s after a payment broadcast took 62.6 s and 69.3 s (Deferred session restoration, 3–4 concurrent_update). A launch 12 s after a sharing toggle settled took 63.4 s on one simulator and 6 min 2 s on the other (SharedStateBusy … pending writes could not be ruled out, then nothing for five minutes). Until the session restores there is no bell, activity rows lose the contact name, and contact deeplinks fail. Full table: #856 (review)

  14. ben-kaufman commented on Oct 6, 2026

    @ben-kaufman
    Contributor

    Thanks, the rc65 run confirms the slow relaunch is not Android-only. I recorded the matching Android evidence in synonymdev/bitkit-android#1419. Quiet restoration and restoration after interrupted writes need to stay separate in the measurements. The pending-write wait must remain until we can prove a previous write cannot still finish; these timings do not justify clearing its marker or shortening the safety interval.

    Keeping this open. The rc65 atomic contact import fix does not resolve the cold-launch delay or the temporary loss of contact names, bell and deeplink availability during restoration.

  15. ben-kaufman commented on Oct 7, 2026

    @ben-kaufman
    Contributor

    Published rc66 check with two fresh staging wallets and regtest funds: both directions completed a 5,000-sat request payment, with receiver credit and independently confirmed chain transactions. App builds were iOS a04232f and Android fd04581d2, before the later link-preparation changes. These are single runs, not a matched before/after benchmark.

    For the iOS payer:

    • Pay on a saved request: preparation preview by 0.92s; private payment opened at 3.745s.
    • Swipe to private-list consumption: 6.810s.
    • Local acceptance record to wallet entry: 2.845s, enclosing the combined claim-and-accept call, not an isolated SDK measurement.
    • Wallet entry to LDK send: 3.096s, including pre-broadcast proof/authorization work.
    • LDK send to successful broadcast: 0.443s. Total swipe-command to broadcast: 13.208s; Sent observed by 16.722s.
    • A reverse-direction Send Request showed Sent within 23.81s. Warm Request-or-Pay appeared within 0.46s.

    The logs do not split SDK queue wait, homeserver locks, state reads/commits and Noise within those intervals. Initial linking, exact request-delivery timing, cold-start and many-contact performance remain open. This does not resolve the failure/recovery journeys or establish the performance of the newer heads. Transaction: 53f92e55d1eaee0cc3892191026b04e593ed028eeffe42da40c90fd12cba4683, confirmed at regtest height 216148.

  16. 6 remaining items

  17. ovitrif commented on Oct 15, 2026

    @ovitrif
    Collaborator

    @ovitrif Could you attach the redacted app trace around the 47-second resume sample, or capture one bounded repeat with your isolated buyer/seller fixture? Please include the exact error line/call site and timestamps for foreground/auth state, import commit and fresh contact read, preparation enqueue/start, and SDK queue admission/start/completion until the seller's first link call. Record whether the contact snapshot or sign-in generation changed.

    @ben-kaufman The earlier trace is gone, so I ran one bounded repeat on e3796d9. sessionNotActive did not reproduce. The delay did, and it was longer. The new seller was imported 20 s after foreground. Its preparation was then dropped at PrivatePaykitService+Contacts.swift:112 and never re-queued, so no link call ran until the next foreground. I brought Bitkit back to the foreground by hand about 5 min after the import, and its first link call came 5 min 19 s after the import. Without that foreground, the wait lasts until some other trigger (foreground, node running, network restored). Auth and sign-in stayed current throughout. The SDK queue never held a preparation call for more than 3.1 s.

    UTC Event Call site (e3796d9)
    10:43:29.8 Bitkit in background; seller S3's marker written at 10:43:34 AppScene.swift:1233
    10:44:01.415 Foreground (active), same process AppScene.swift:1233
    10:44:01.904 Foreground sync done, authenticated; old snapshot (S1, S2) enqueued, preparation starts at once AppScene.swift:1279–1283 → :1326, Contacts.swift:114–115
    10:44:04.5–11.2 S1/S2 preparation: linkedPeers waits 3.08 s in the SDK queue; each ensureLinkWithPeer waits ≤0.7 s and runs ≤1.6 s; publication check passes, no error Contacts.swift:686–727
    10:44:20.108 Importer finds S3. Its key sorts before S1/S2, so it appears only after the cursor wraps ShopContactImporter.swift:60
    10:44:21.633 importShopContacts commits (SDK queue wait 0.14 s) and the fresh contact read starts ShopContactImporter.swift:88–91
    10:44:22.277 savedContactsChanged with 3 keys starts prepareSavedPaykitContacts ContactsManager.swift:396 → AppScene.swift:625–633
    10:44:22.283 Dropped: revision == savedContactsRevision fails, returns nil, nothing enqueued Contacts.swift:112
    10:44:22.284 Fresh read done (3 contacts) ContactsManager.swift:411
    10:44:22 → 10:49:21 No preparation and no ensureLinkWithPeer for about 5 min while the app stayed in front —
    10:49:21.882 → 10:49:32.807 Background, then a second foreground, done by hand to end the wait AppScene.swift:1233
    10:49:33.233 All three keys enqueued; preparation starts Contacts.swift:114–115, :241–242
    10:49:40.187 First ensureLinkWithPeer for S3 (SDK queue wait 0.70 s) Contacts.swift:694 → PubkyService.swift:957

    Why it was dropped. ContactsManager.loadContacts assigns contacts at :396, and that publishes savedContactsChanged. The same call then reaches pruneUnsavedContactState at :407, which calls rememberSavedContacts(replacing: true). That bumps savedContactsRevision (Contacts.swift:1308) between the preparation's read at :109 and its guard at :112, so the import-triggered preparation sees a moved revision and returns. The bump itself was not logged. It follows from the code order and the timestamps: the drop is at 22.283, and Loaded 3 contacts (:411, after the prune) is at 22.284.

    The open-app path shows the same drop. S1 and S2 were imported at 10:36:31.7, their preparation was dropped at 10:36:32.001 the same way, and they got no link call for 7.5 min, until the resume above. The drop is a race: the prepare's read and guard run against the prune at ContactsManager.swift:407. It lost on both imports in this run. The earlier e3796d9 open-app sample did get a link call, 72 s after import, so either the race does not lose every time or another trigger fired then. That run has no log to say which.

    Your questions.

    • Sign-in generation: unchanged. isSessionCurrent never returned false; I logged each of its three conditions separately. Auth stayed authenticated the whole run.
    • Contact snapshot: it changed once, from 2 to 3 keys, at the import. The drop comes from the revision check, not from the snapshot closure.
    • Obsolete work: none. The old-snapshot run finished at 10:44:11, 10 s before the import, so it never reached the :727 throw. That is the likely reason no sessionNotActive appeared this time.
    • Lost retry or SDK time: a lost retry. SDK queue waits were at most 3.1 s and each SDK call ran at most 1.9 s.

    On the rc75 sample: the import landed 3 s after foreground there, so the old-snapshot run would still have been in flight and could fail at :727. That fits the sessionNotActive we saw, with the new seller's own preparation dropped as here. This run does not prove it. Note also that the 47 s there ran from foreground to link, about 44 s after import, and that run has no log of what started the link.

    Setup.

    • Build: Debug regtest build of e3796d9 against staging. The head has not moved past e3796d9.
    • Device: iPhone 17 simulator on iOS 26.5, fresh install.
    • Accounts: a fresh buyer created in Bitkit with contact payments on, and three fresh staging sellers, each publishing a valid shop.json.
    • Markers: written to the buyer's seller-auto-follow/v1/ folder.
    • Seller links: the fixture sellers publish no Paykit, so every ensureLinkWithPeer ended in NotFound. The trace times when the link call starts, not a completed link.
    • Logging: the build adds local log lines only (diff below, not pushed). Line numbers in the table are e3796d9's; the excerpt's are the logging build's.

    Recording at 2x: background with Settings in front, the marker written, foreground, then the second background and foreground.

    resume.2x.mp4
    Log excerpt (UTC, keys shortened)
    10:43:26.970 INFO AppScene.swift:1234  Scene phase changed: inactive
    10:43:29.832 INFO AppScene.swift:1234  Scene phase changed: background
    10:44:00.983 INFO AppScene.swift:1234  Scene phase changed: inactive
    10:44:01.415 INFO AppScene.swift:1234  Scene phase changed: active
    10:44:01.430 INFO ContactsManager.swift:383  Loading contacts for pubkyjrwya4a...
    10:44:01.904 INFO AppScene.swift:1281  foregroundSync done active=true auth=authenticated
    10:44:01.904 INFO AppScene.swift:1330  prepareSavedPaykitContacts[6325] snapshot=2 keys=["pubkypcgpncj...", "pubky6rr6dtj..."] expectedIdentity=false
    10:44:01.904 INFO PrivatePaykitService+Contacts.swift:115  prepareSavedContacts enqueue keys=["pubkypcgpncj...", "pubky6rr6dtj..."] taskRunning=false active=0
    10:44:01.905 INFO PrivatePaykitService+Contacts.swift:243  preparation start keys=["pubky6rr6dtj...", "pubkypcgpncj..."]
    10:44:01.923 INFO ContactsManager.swift:411  Loaded 2 contacts
    10:44:02.599 INFO PrivatePaykitService+Contacts.swift:670  syncLocalEndpointPublication start reason=contact preparation keys=["pubky6rr6dtj...", "pubkypcgpncj..."]
    10:44:04.520 INFO PubkyService.swift:1703  sdkLock admit[AFD3] linkedPeers(priority:) prio=background locked=true waiters=1
    10:44:07.607 INFO PubkyService.swift:1705  sdkLock start[AFD3] linkedPeers(priority:) waited=3.08s
    10:44:07.971 INFO PubkyService.swift:1707  sdkLock done[AFD3] linkedPeers(priority:) total=3.45s
    10:44:07.977 INFO PrivatePaykitService+Contacts.swift:698  link step pubky6rr6dtj... state=nil
    10:44:07.977 INFO PubkyService.swift:1703  sdkLock admit[C8FF] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) prio=background locked=true waiters=1
    10:44:08.307 INFO PubkyService.swift:1703  sdkLock admit[6A6C] linkedPeers(priority:) prio=background locked=true waiters=1
    10:44:08.602 INFO PubkyService.swift:1703  sdkLock admit[440D] linkedPeers(priority:) prio=background locked=true waiters=1
    10:44:08.602 INFO PubkyService.swift:1705  sdkLock start[C8FF] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) waited=0.62s
    10:44:09.208 INFO PubkyService.swift:1707  sdkLock done[C8FF] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) total=1.23s
    10:44:09.209 INFO PubkyService.swift:1705  sdkLock start[6A6C] linkedPeers(priority:) waited=0.90s
    10:44:09.212 INFO PrivatePaykitService+Contacts.swift:707  link NotFound pubky6rr6dtj... -> 5 min skip
    10:44:09.213 INFO PrivatePaykitService+Contacts.swift:698  link step pubkypcgpncj... state=nil
    10:44:09.213 INFO PubkyService.swift:1703  sdkLock admit[0962] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) prio=background locked=true waiters=1
    10:44:09.544 INFO PubkyService.swift:1707  sdkLock done[6A6C] linkedPeers(priority:) total=1.24s
    10:44:09.545 INFO PubkyService.swift:1705  sdkLock start[440D] linkedPeers(priority:) waited=0.94s
    10:44:09.879 INFO PubkyService.swift:1707  sdkLock done[440D] linkedPeers(priority:) total=1.28s
    10:44:09.883 INFO PubkyService.swift:1705  sdkLock start[0962] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) waited=0.67s
    10:44:10.826 INFO PubkyService.swift:1707  sdkLock done[0962] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) total=1.62s
    10:44:10.828 INFO PrivatePaykitService+Contacts.swift:707  link NotFound pubkypcgpncj... -> 5 min skip
    10:44:10.830 INFO PrivatePaykitService+Contacts.swift:734  publication lock wait prepared=0 retry=0
    10:44:10.830 INFO PrivatePaykitService+Contacts.swift:736  publication lock acquired
    10:44:11.170 INFO PrivatePaykitService+Contacts.swift:245  preparation end pending=0
    10:44:20.108 INFO ShopContactImporter.swift:61  importer page listed=3
    10:44:20.748 INFO ShopContactImporter.swift:89  importer save start sellers=["pubky5n8gn5q..."]
    10:44:20.748 INFO PubkyService.swift:1703  sdkLock admit[B8D9] importShopContacts(publicKeys:expectedIdentity:isStillCurrent:) prio=background locked=true waiters=0
    10:44:20.895 INFO PubkyService.swift:1705  sdkLock start[B8D9] importShopContacts(publicKeys:expectedIdentity:isStillCurrent:) waited=0.14s
    10:44:21.632 INFO PubkyService.swift:1707  sdkLock done[B8D9] importShopContacts(publicKeys:expectedIdentity:isStillCurrent:) total=0.88s
    10:44:21.633 INFO ShopContactImporter.swift:91  importer save committed changed=true
    10:44:21.633 INFO ContactsManager.swift:383  Loading contacts for pubkyjrwya4a...
    10:44:22.277 INFO AppScene.swift:632  savedContactsChanged count=3
    10:44:22.282 INFO AppScene.swift:1330  prepareSavedPaykitContacts[CCC5] snapshot=3 keys=["pubky5n8gn5q...", "pubkypcgpncj...", "pubky6rr6dtj..."] expectedIdentity=true
    10:44:22.283 INFO PrivatePaykitService+Contacts.swift:112  prepareSavedContacts dropped: revision/generation moved
    10:44:22.284 INFO ContactsManager.swift:411  Loaded 3 contacts
    10:44:22.284 INFO ShopContactImporter.swift:95  importer contact refresh done
    …   idle: importer polls every ~11 s and background linkedPeers reads every ~1 min; no preparation, no ensureLinkWithPeer
    10:49:21.882 INFO AppScene.swift:1234  Scene phase changed: inactive
    10:49:22.716 INFO AppScene.swift:1234  Scene phase changed: background
    10:49:32.366 INFO AppScene.swift:1234  Scene phase changed: inactive
    10:49:32.807 INFO AppScene.swift:1234  Scene phase changed: active
    10:49:32.822 INFO ContactsManager.swift:383  Loading contacts for pubkyjrwya4a...
    10:49:33.227 INFO AppScene.swift:1281  foregroundSync done active=true auth=authenticated
    10:49:33.228 INFO AppScene.swift:1330  prepareSavedPaykitContacts[9B53] snapshot=3 keys=["pubkypcgpncj...", "pubky6rr6dtj...", "pubky5n8gn5q..."] expectedIdentity=false
    10:49:33.233 INFO PrivatePaykitService+Contacts.swift:115  prepareSavedContacts enqueue keys=["pubkypcgpncj...", "pubky6rr6dtj...", "pubky5n8gn5q..."] taskRunning=false active=0
    10:49:33.233 INFO PrivatePaykitService+Contacts.swift:243  preparation start keys=["pubky5n8gn5q...", "pubky6rr6dtj...", "pubkypcgpncj..."]
    10:49:33.371 INFO ContactsManager.swift:411  Loaded 3 contacts
    10:49:33.959 INFO PrivatePaykitService+Contacts.swift:670  syncLocalEndpointPublication start reason=contact preparation keys=["pubky5n8gn5q...", "pubky6rr6dtj...", "pubkypcgpncj..."]
    10:49:36.219 INFO PubkyService.swift:1703  sdkLock admit[DE74] linkedPeers(priority:) prio=background locked=true waiters=1
    10:49:39.188 INFO PubkyService.swift:1705  sdkLock start[DE74] linkedPeers(priority:) waited=2.97s
    10:49:39.475 INFO PubkyService.swift:1707  sdkLock done[DE74] linkedPeers(priority:) total=3.26s
    10:49:39.480 INFO PrivatePaykitService+Contacts.swift:698  link step pubky5n8gn5q... state=nil
    10:49:39.480 INFO PubkyService.swift:1703  sdkLock admit[0110] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) prio=background locked=true waiters=1
    10:49:39.842 INFO PubkyService.swift:1703  sdkLock admit[3206] linkedPeers(priority:) prio=background locked=true waiters=1
    10:49:40.187 INFO PubkyService.swift:1705  sdkLock start[0110] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) waited=0.70s
    10:49:40.189 INFO PubkyService.swift:1703  sdkLock admit[4562] linkedPeers(priority:) prio=background locked=true waiters=1
    10:49:40.908 INFO PubkyService.swift:1707  sdkLock done[0110] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) total=1.43s
    10:49:40.911 INFO PrivatePaykitService+Contacts.swift:707  link NotFound pubky5n8gn5q... -> 5 min skip
    10:49:40.911 INFO PrivatePaykitService+Contacts.swift:698  link step pubky6rr6dtj... state=nil
    10:49:40.912 INFO PubkyService.swift:1703  sdkLock admit[77EE] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) prio=background locked=true waiters=1
    10:49:40.912 INFO PubkyService.swift:1705  sdkLock start[3206] linkedPeers(priority:) waited=1.07s
    10:49:41.288 INFO PubkyService.swift:1707  sdkLock done[3206] linkedPeers(priority:) total=1.45s
    10:49:41.289 INFO PubkyService.swift:1705  sdkLock start[4562] linkedPeers(priority:) waited=1.10s
    10:49:41.758 INFO PubkyService.swift:1707  sdkLock done[4562] linkedPeers(priority:) total=1.57s
    10:49:41.759 INFO PubkyService.swift:1705  sdkLock start[77EE] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) waited=0.85s
    10:49:42.809 INFO PubkyService.swift:1707  sdkLock done[77EE] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) total=1.90s
    10:49:42.810 INFO PrivatePaykitService+Contacts.swift:707  link NotFound pubky6rr6dtj... -> 5 min skip
    10:49:42.811 INFO PrivatePaykitService+Contacts.swift:698  link step pubkypcgpncj... state=nil
    10:49:42.812 INFO PubkyService.swift:1703  sdkLock admit[1D8C] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) prio=background locked=false waiters=0
    10:49:42.812 INFO PubkyService.swift:1705  sdkLock start[1D8C] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) waited=0.00s
    10:49:43.565 INFO PubkyService.swift:1707  sdkLock done[1D8C] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) total=0.76s
    10:49:43.569 INFO PrivatePaykitService+Contacts.swift:707  link NotFound pubkypcgpncj... -> 5 min skip
    10:49:43.571 INFO PrivatePaykitService+Contacts.swift:734  publication lock wait prepared=0 retry=0
    10:49:43.571 INFO PrivatePaykitService+Contacts.swift:736  publication lock acquired
    
    Logging diff applied for this run
    diff --git a/Bitkit/AppScene.swift b/Bitkit/AppScene.swift
    index 6f46323c..f61a6060 100644
    --- a/Bitkit/AppScene.swift
    +++ b/Bitkit/AppScene.swift
    @@ -629,6 +629,7 @@ struct AppScene: View {
                           pubkyProfile.authState == .authenticated, let pk = pubkyProfile.publicKey
                     else { return }
                     paykitPaymentRequestManager.updateSavedPublicKeys(publicKeys)
    +                Logger.info("R868 savedContactsChanged count=\(publicKeys.count)", context: "R868")
                     Task {
                         await prepareSavedPaykitContacts(expectedIdentity: pk)
                         guard isPaykitSceneActive, pubkyProfile.authState == .authenticated,
    @@ -1277,6 +1278,7 @@ struct AppScene: View {
                     foregroundWalletSync = foregroundSync
                     Task {
                         await foregroundSync.value
    +                    Logger.info("R868 foregroundSync done active=\(isPaykitSceneActive) auth=\(pubkyProfile.authState)", context: "R868")
                         guard isPaykitSceneActive else { return }
                         if PaykitFeatureFlags.isUIEnabled {
                             await refreshPrivateOnlyPaykitApp()
    @@ -1324,9 +1326,17 @@ struct AppScene: View {
                   expectedIdentity == nil || PubkyPublicKeyFormat.matches(expectedIdentity, session.publicKey)
             else { return }
             let snapshot = contactsManager.savedContactsSnapshot()
    +        let r868ID = String(UUID().uuidString.prefix(4))
    +        Logger.info("R868 prepareSavedPaykitContacts[\(r868ID)] snapshot=\(snapshot.publicKeys.count) keys=\(snapshot.publicKeys.map { PubkyPublicKeyFormat.redacted($0) }) expectedIdentity=\(expectedIdentity != nil)", context: "R868")
             await PrivatePaykitService.shared.prepareSavedContacts(
                 snapshot.publicKeys, wallet: wallet, isSessionCurrent: {
    -                pubkyProfile.authState == .authenticated && pubkyProfile.currentSession == session && snapshot.isCurrent()
    +                let auth = pubkyProfile.authState == .authenticated
    +                let sameSession = pubkyProfile.currentSession == session
    +                let snapCurrent = snapshot.isCurrent()
    +                if !(auth && sameSession && snapCurrent) {
    +                    Logger.info("R868 isSessionCurrent[\(r868ID)]=false authenticated=\(auth) sameSession=\(sameSession) snapshotCurrent=\(snapCurrent)", context: "R868")
    +                }
    +                return auth && sameSession && snapCurrent
                 }
             )
         }
    diff --git a/Bitkit/Managers/ShopContactImporter.swift b/Bitkit/Managers/ShopContactImporter.swift
    index 9c580f79..865d9214 100644
    --- a/Bitkit/Managers/ShopContactImporter.swift
    +++ b/Bitkit/Managers/ShopContactImporter.swift
    @@ -58,6 +58,7 @@ final class ShopContactImporter {
             let buyer = String(normalized.dropFirst(5))
             let root = "pubky://\(buyer)\(Self.markerPath)"
             let page = try await listPage(root, cursor, Self.pageSize)
    +        Logger.info("R868 importer page listed=\(page.count)", context: "R868")
             try requireCurrent(isCurrent)
             var sellers: [String] = []
             for uri in page {
    @@ -85,10 +86,13 @@ final class ShopContactImporter {
             try requireCurrent(isCurrent)
             // A cancelled write may have committed; refresh before further discovery on retry.
             refreshPending = !sellers.isEmpty
    +        if !sellers.isEmpty { Logger.info("R868 importer save start sellers=\(sellers.map { PubkyPublicKeyFormat.redacted("pubky" + $0) })", context: "R868") }
             let changed = try await saveContacts(sellers.map { "pubky\($0)" }, publicKey, { await isCurrent() })
    +        if !sellers.isEmpty { Logger.info("R868 importer save committed changed=\(changed)", context: "R868") }
             try requireCurrent(isCurrent)
             if refreshPending {
                 try await refreshContacts()
    +            Logger.info("R868 importer contact refresh done", context: "R868")
                 try requireCurrent(isCurrent)
                 refreshPending = false
             }
    diff --git a/Bitkit/Services/PrivatePaykitService+Contacts.swift b/Bitkit/Services/PrivatePaykitService+Contacts.swift
    index f1ca1f06..7e0c2f6f 100644
    --- a/Bitkit/Services/PrivatePaykitService+Contacts.swift
    +++ b/Bitkit/Services/PrivatePaykitService+Contacts.swift
    @@ -108,10 +108,11 @@ extension PrivatePaykitService {
         ) async -> Error? {
             let revision = savedContactsRevision
             let generation = preparationGeneration
    -        if let isSessionCurrent, await !isSessionCurrent() { return nil }
    -        guard revision == savedContactsRevision, generation == preparationGeneration else { return nil }
    +        if let isSessionCurrent, await !isSessionCurrent() { Logger.info("R868 prepareSavedContacts dropped: session not current at entry", context: "R868"); return nil }
    +        guard revision == savedContactsRevision, generation == preparationGeneration else { Logger.info("R868 prepareSavedContacts dropped: revision/generation moved", context: "R868"); return nil }
             if !requireImmediatePublication {
                 let keys = rememberSavedContacts(publicKeys, replacing: true)
    +            Logger.info("R868 prepareSavedContacts enqueue keys=\(keys.map { PubkyPublicKeyFormat.redacted($0) }) taskRunning=\(preparationTask != nil) active=\(activePreparationKeys.count)", context: "R868")
                 scheduleContactPreparation(keys, wallet: wallet, isSessionCurrent: isSessionCurrent)
                 return nil
             }
    @@ -239,7 +240,9 @@ extension PrivatePaykitService {
                     pendingPreparationOperation = nil
                     pendingForceRefreshLightning = false
                     activePreparationKeys = keys
    +                Logger.info("R868 preparation start keys=\(Array(keys).sorted().map { PubkyPublicKeyFormat.redacted($0) })", context: "R868")
                     await operation(Array(keys).sorted(), forceRefresh)
    +                Logger.info("R868 preparation end pending=\(pendingPreparationKeys.count)", context: "R868")
                     activePreparationKeys.removeAll()
                 }
             }
    @@ -304,15 +307,16 @@ extension PrivatePaykitService {
             reason: String = "refresh",
             isSessionCurrent: (@MainActor () -> Bool)? = nil
         ) async -> Error? {
    -        if let isSessionCurrent, await !isSessionCurrent() { return nil }
    +        if let isSessionCurrent, await !isSessionCurrent() { Logger.info("R868 refreshSavedContactEndpoints dropped: session not current", context: "R868"); return nil }
             let generation = preparationGeneration
    -        if !requireImmediatePublication, await !waitForBackgroundWork(generation: generation) { return nil }
    +        if !requireImmediatePublication, await !waitForBackgroundWork(generation: generation) { Logger.info("R868 refreshSavedContactEndpoints dropped: background wait", context: "R868"); return nil }
             let operations = endpointPublicationOperations(
                 wallet: wallet,
                 forceRefreshLightning: forceRefreshLightning,
                 readPriority: requireImmediatePublication ? .ordered : .background
             )
             guard await operations.canPublish() else {
    +            Logger.info("R868 canPublish=false -> prepareRelevantPrivateLinksIfAvailable", context: "R868")
                 await prepareRelevantPrivateLinksIfAvailable(publicKeys, reason: reason, isBackgroundWork: !requireImmediatePublication)
                 return requireImmediatePublication && !publicKeys.isEmpty ? PrivatePaykitError.privateUnavailable : nil
             }
    @@ -353,7 +357,7 @@ extension PrivatePaykitService {
     
             do {
                 try await withPublicationLock {
    -                if let isSessionCurrent, await !isSessionCurrent() { throw PubkyServiceError.sessionNotActive }
    +                if let isSessionCurrent, await !isSessionCurrent() { Logger.info("R868 THROW sessionNotActive at Contacts.swift:356 (e3796d9)", context: "R868"); throw PubkyServiceError.sessionNotActive }
                     try await removePublishedEndpointsLocked(
                         for: publicKeys, isSessionCurrent: isSessionCurrent, revision: revision, generation: generation, operations: operations
                     )
    @@ -663,6 +667,7 @@ extension PrivatePaykitService {
             operations: EndpointPublicationOperations
         ) async -> Error? {
             let publicKeys = normalizedSavedContactKeys(publicKeys)
    +        Logger.info("R868 syncLocalEndpointPublication start reason=\(reason) keys=\(publicKeys.map { PubkyPublicKeyFormat.redacted($0) })", context: "R868")
             guard !publicKeys.isEmpty else { return nil }
     
             let generation = preparationGeneration
    @@ -688,15 +693,18 @@ extension PrivatePaykitService {
                 guard generation == preparationGeneration else { break }
                 guard knownSavedContactKeys.contains(publicKey), !UserDefaults.standard.bool(forKey: Self.cleanupPendingKey) else { continue }
                 if peerStates[publicKey] == .blocked { continue }
    -            if !requireImmediatePublication, let retryAt = unavailableLinkRetryAt[publicKey], retryAt > messageRetryOperations.now() { continue }
    +            if !requireImmediatePublication, let retryAt = unavailableLinkRetryAt[publicKey], retryAt > messageRetryOperations.now() { Logger.info("R868 skip \(PubkyPublicKeyFormat.redacted(publicKey)): retry window", context: "R868"); continue }
                 do {
    +                Logger.info("R868 link step \(PubkyPublicKeyFormat.redacted(publicKey)) state=\(String(describing: peerStates[publicKey]))", context: "R868")
                     if peerStates[publicKey] != .linked,
                        try await withLinkPreparation(publicKey, operation: { try await operations.ensureLink(publicKey) }) != .linked
                     {
                         linkRetryKeys.append(publicKey)
                     }
    +                Logger.info("R868 link step done \(PubkyPublicKeyFormat.redacted(publicKey))", context: "R868")
                     unavailableLinkRetryAt[publicKey] = nil
                 } catch PaykitError.NotFound {
    +                Logger.info("R868 link NotFound \(PubkyPublicKeyFormat.redacted(publicKey)) -> 5 min skip", context: "R868")
                     unavailableLinkRetryAt[publicKey] = messageRetryOperations.now().addingTimeInterval(5 * 60)
                     continue
                 } catch {
    @@ -723,8 +731,10 @@ extension PrivatePaykitService {
             do {
                 if !requireImmediatePublication, await !waitForBackgroundWork(generation: generation) { return nil }
                 // Do not wait for foreground while holding a publication batch.
    +            Logger.info("R868 publication lock wait prepared=\(preparedKeys.count) retry=\(linkRetryKeys.count)", context: "R868")
                 try await withPublicationLock {
    -                if let isSessionCurrent, await !isSessionCurrent() { throw PubkyServiceError.sessionNotActive }
    +                Logger.info("R868 publication lock acquired", context: "R868")
    +                if let isSessionCurrent, await !isSessionCurrent() { Logger.info("R868 THROW sessionNotActive at Contacts.swift:727 (e3796d9)", context: "R868"); throw PubkyServiceError.sessionNotActive }
                     guard generation == preparationGeneration,
                           await operations.currentPublicKey() == identity,
                           !UserDefaults.standard.bool(forKey: Self.cleanupPendingKey)
    diff --git a/Bitkit/Services/PubkyService.swift b/Bitkit/Services/PubkyService.swift
    index e9ba1768..8ddd8e1a 100644
    --- a/Bitkit/Services/PubkyService.swift
    +++ b/Bitkit/Services/PubkyService.swift
    @@ -1330,13 +1330,14 @@ actor PaykitSdkService {
         private func withSdk<T>(
             priority: PaykitSdkOperationLock.Priority = .ordered,
             deferDuringPayment: Bool = false,
    +        caller: String = #function,
             _ operation: (PaykitSdk) async throws -> T
         ) async throws -> T {
             let generation = deferDuringPayment ? try operationLock.walletGeneration() : nil
             let instance = deferDuringPayment ? try handle() : nil
             while true {
                 if deferDuringPayment { try await PaykitPaymentActivity.shared.waitUntilIdle() }
    -            let result: T? = try await operationLock.withLock(priority: priority) {
    +            let result: T? = try await operationLock.withLock(priority: priority, caller: caller) {
                     if let instance {
                         guard sdk === instance, try operationLock.walletGeneration() == generation else {
                             throw PubkyServiceError.identityChanged
    @@ -1376,9 +1377,10 @@ actor PaykitSdkService {
         private func withStateRevisionTracking<T>(
             priority: PaykitSdkOperationLock.Priority = .ordered,
             deferDuringPayment: Bool = false,
    +        caller: String = #function,
             _ operation: (PaykitSdk) async throws -> T
         ) async throws -> T {
    -        try await withSdk(priority: priority, deferDuringPayment: deferDuringPayment) { sdk in
    +        try await withSdk(priority: priority, deferDuringPayment: deferDuringPayment, caller: caller) { sdk in
                 return try await Self.withBackupStateRevisionTracking(
                     readRevision: { try await self.withSdkErrorHandling { try await sdk.backupStateRevision() } },
                     readStateRevision: { try sdk.stateRevision() },
    @@ -1691,17 +1693,31 @@ final class PaykitSdkOperationLock: @unchecked Sendable {
         func withLock<T>(
             priority: Priority = .ordered,
             generation expectedGeneration: Int? = nil,
    +        caller: String = #function,
             _ operation: () async throws -> T
         ) async throws -> T {
             if ownsWipe() { return try await operation() }
             let admittedGeneration = try admit()
    +        let r868ID = String(UUID().uuidString.prefix(4))
    +        let r868Admit = Date()
    +        Logger.info("R868 sdkLock admit[\(r868ID)] \(caller) prio=\(priority) \(r868State())", context: "R868")
             await acquire(priority: priority)
    -        defer { release() }
    +        Logger.info("R868 sdkLock start[\(r868ID)] \(caller) waited=\(String(format: "%.2f", Date().timeIntervalSince(r868Admit)))s", context: "R868")
    +        defer {
    +            Logger.info("R868 sdkLock done[\(r868ID)] \(caller) total=\(String(format: "%.2f", Date().timeIntervalSince(r868Admit)))s", context: "R868")
    +            release()
    +        }
             try validate(expectedGeneration ?? admittedGeneration)
             try Task.checkCancellation()
             return try await operation()
         }
     
    +    private func r868State() -> String {
    +        lock.lock()
    +        defer { lock.unlock() }
    +        return "locked=\(isLocked) waiters=\(waiters.count)"
    +    }
    +
         func walletGeneration() throws -> Int {
             try admit()
         }
  18. added this to the 3.0.0 milestone on Oct 15, 2026
  19. ben-kaufman commented on Oct 15, 2026

    @ben-kaufman
    Contributor

    Thanks, this trace let us reproduce the dropped preparation in a deterministic test. The preparation's session check suspends on MainActor; pruning can advance the service revision while it is suspended, and the original guard then discards the still-current snapshot.

    The fix is pushed in #934 at 734e020d30005ab86384048249922d2d9aada3bd. It revalidates that snapshot until the revision is stable, retaining the original preparation generation and still rejecting removed contacts, ended sessions, invalidation and cancellation. No SDK request, polling interval or safety wait was added or changed. The regression fails against the previous source; all five table cases pass with the fix, along with 226 focused tests and 2,572 native unit tests. Current master is integrated and the navigation conflict resolved; diagnostics were compared with clean master with no introduced findings.

    @ovitrif Please repeat the bounded already-open and background/resume cases on the updated #934 head, including a newly inserted seller sorting before the scan cursor. After import, leave Bitkit foregrounded without visiting Contacts or triggering another foreground. Record import commit, preparation enqueue/start and first ensureLinkWithPeer admission/start. The new seller's first link call should start automatically. Your storefront-only sellers are sufficient for this scheduling check; successful linking needs a Paykit-capable seller and is a separate assertion. No funding, approval or payment is needed.

    Keeping #934 draft until the remaining acceptance checks. This fixes the reproduced lost-preparation race, not every latency report: the earlier 47-second sessionNotActive sample remains unproven, and the reported 5m19s was time until another trigger, not evidence of the uncertain-write safety wait.

  20. ovitrif commented on Oct 15, 2026

    @ovitrif
    Collaborator

    @ben-kaufman The bounded repeat you asked for ran on #934 at 734e020: results.

    • Before, on e3796d9: a newly imported seller's preparation was dropped and got no link call until the next trigger: 5 min 19 s after a background import (ended by a manual foreground), and 7.5 min for sellers imported while the app was open.
    • After, on 734e020: the same race fired on every import and was revalidated. The new seller's first ensureLinkWithPeer started 2.4 s after the import commit with the app open, 8.5 s after background then foreground, 14.5 s on a cold open, 2.9 s on the existing poll with the Send sheet open, and 13.1 s after an interrupted refresh. Bitkit was left alone each time.
    • sessionNotActive: thrown twice, by an older snapshot's run still in flight, and harmless now: the queued preparation started within 22 ms.
    • Still open: a completed link and a real Shop request reaching payment review. Both need a Paykit-capable seller.
  21. ben-kaufman commented on Oct 15, 2026

    @ben-kaufman
    Contributor

    Thanks, this confirms the reproduced lost-preparation race is fixed in #934 at 734e020. I've recorded the current-head retest in that PR: first link calls now start automatically in the five reported scenarios, without the extra trigger the old build needed.

    Keeping #868 open. These are import-commit-to-first-call measurements, not completed-link or Shop-checkout timings. The two obsolete-snapshot errors in this run did not lose the queued work, but they do not prove the cause of the earlier RC75 47-second delay. Completed linking and request-to-review still need the Paykit-capable seller fixture. Repeated unreachable-seller lookups remain a separate, non-blocking optimization candidate.

  22. modified the milestones: 3.0.0, 3.0.1 on Oct 15, 2026
  23. ovitrif commented on Oct 15, 2026

    @ovitrif
    Collaborator

    In 3.0.5: the dropped-preparation race found here is fixed in #934 for 3.0.0; what stays open is explaining the original 47 s sessionNotActive sample, which doesn't block the release.

  24. modified the milestones: 3.0.1, 3.0.5 on Oct 15, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions