From 4a12e40549d18f4a2621d061ef487b4b9461fad9 Mon Sep 17 00:00:00 2001 From: Jonathan Tzeng Date: Mon, 20 Jul 2026 10:47:56 -0700 Subject: [PATCH 1/2] Log NYM mixFetch request lifecycle The 2026-07-20 QA report on staging 26071707 shows NYM requests failing with 'panic:todo: extract error message', a placeholder the mix-fetch v1 Go layer emits in place of the real reason. Our own logging recorded only mixFetch setup, so a wedged request could not be attributed to a host or endpoint. Log each mixnet request on the way out and once when it settles, with the method, host, path, elapsed time, and either the HTTP status or the raw error text. A start line with no matching terminal line is now the signature of a request that never returned. Query strings are omitted because RPC endpoints carry API keys. Both io backends share one wrapper so the browser A/B harness and the app produce the same log shape. --- CHANGELOG.md | 2 + src/io/browser/browser-io.ts | 12 +- src/io/react-native/react-native-worker.ts | 13 +-- src/util/nym.ts | 127 ++++++++++++++++++++- 4 files changed, 129 insertions(+), 25 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index b15bfa580..afcf19620 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,8 @@ ## Unreleased +- added: Log the lifecycle of every NYM mixnet request (method, host, path, duration, HTTP status or error, and in-flight count), plus mixFetch setup timing. A request that logs a start with no terminal line identifies the host whose request never returned, which the previous logging could not attribute. These log at `warn` so they survive the default `warn` log level and appear in a log export without the user first enabling verbose logging. + ## 2.47.1 (2026-07-17) - fixed: Revert `@nymproject/mix-fetch` to v1 (1.4.4), restoring the pinned gateway and network requester. The v2 stack shipped in 2.47.0 fails to complete small HTTPS JSON-RPC requests through most exit nodes and its exit-node auto-discovery rarely converges, which left wallets with NYM privacy enabled unable to sync or send. diff --git a/src/io/browser/browser-io.ts b/src/io/browser/browser-io.ts index 929582467..aa1dae77b 100644 --- a/src/io/browser/browser-io.ts +++ b/src/io/browser/browser-io.ts @@ -3,7 +3,7 @@ import { makeLocalStorageDisklet } from 'disklet' import { LogBackend, makeLog } from '../../core/log/log' import { EdgeFetchOptions, EdgeFetchResponse, EdgeIo } from '../../types/types' import { scrypt } from '../../util/crypto/scrypt' -import { initMixFetch, mixFetchOptions } from '../../util/nym' +import { nymFetch } from '../../util/nym' import { fetchCorsProxy } from './fetch-cors-proxy' // Only try CORS proxy/bridge techniques up to 5 times @@ -49,15 +49,7 @@ export function makeBrowserIo(logBackend: LogBackend): EdgeIo { const { corsBypass = 'auto', privacy = 'none' } = opts ?? {} if (privacy === 'nym') { - const nymFetch = await initMixFetch(log) - return await nymFetch( - uri, - { - ...opts, - mode: 'unsafe-ignore-cors' as RequestMode - }, - mixFetchOptions - ) + return await nymFetch(uri, opts ?? {}, log) } if (corsBypass === 'always') { return await fetchCorsProxy(uri, opts) diff --git a/src/io/react-native/react-native-worker.ts b/src/io/react-native/react-native-worker.ts index 4eb777c89..1c096a889 100644 --- a/src/io/react-native/react-native-worker.ts +++ b/src/io/react-native/react-native-worker.ts @@ -17,7 +17,7 @@ import { EdgeFetchResponse, EdgeIo } from '../../types/types' -import { initMixFetch, mixFetchOptions } from '../../util/nym' +import { nymFetch } from '../../util/nym' import { hideProperties } from '../hidden-properties' import { makeNativeBridge } from './native-bridge' import { WorkerApi, YAOB_THROTTLE_MS } from './react-native-types' @@ -176,16 +176,7 @@ async function makeIo(logBackend: LogBackend): Promise { const { corsBypass = 'auto', privacy = 'none' } = opts ?? {} if (privacy === 'nym') { - const nymFetch = await initMixFetch(log) - const response = await nymFetch( - uri, - { - ...opts, - mode: 'unsafe-ignore-cors' as RequestMode - }, - mixFetchOptions - ) - return response + return await nymFetch(uri, opts ?? {}, log) } if (corsBypass === 'always') { return await nativeFetch(uri, opts) diff --git a/src/util/nym.ts b/src/util/nym.ts index 04cb8ff28..3cc657d3f 100644 --- a/src/util/nym.ts +++ b/src/util/nym.ts @@ -6,7 +6,7 @@ import { SetupMixFetchOps } from '@nymproject/mix-fetch' -import { EdgeLog } from '../types/types' +import { EdgeFetchOptions, EdgeFetchResponse, EdgeLog } from '../types/types' /** * Configuration options for the NYM mixFetch client. @@ -35,13 +35,73 @@ const SETUP_TIMEOUT_MS = 60000 // MixFetch initialization state let mixFetchInitPromise: Promise | null = null +// Number of mixnet requests currently awaiting a response. Reported on every +// request line, since a request that never settles is only visible as a count +// that never comes back down. +let inFlightCount = 0 + +// Distinguishes concurrent requests to the same host in the log. +let requestCounter = 0 + +/** + * A path segment that is long and unbroken enough to be an identifier rather + * than a route: an address, a txid, a public key, or an API key. Real route + * segments in the endpoints we call (`ext`, `bc`, `C`, `rpc`, `v2`, `api`, + * `get_address_info`) are short, or contain separators, or both. + */ +const IDENTIFIER_SEGMENT = /^(0x)?[0-9a-zA-Z]{20,}$/ + +/** + * Reduce a request URI to the part that is safe to write to a user's log. + * + * Query strings are dropped entirely because RPC endpoints carry API keys + * there. The path is kept, because two endpoints on one host are often + * different routes and telling them apart is the point of this logging, but + * any segment that looks like an identifier is masked: several chains put a + * wallet address or txid directly in the path, and these lines end up in + * user-uploaded support logs. + */ +function describeUri(uri: string): string { + try { + const { host, pathname } = new URL(uri) + if (pathname === '/') return host + const safePath = pathname + .split('/') + .map(segment => + IDENTIFIER_SEGMENT.test(segment) ? '' : segment + ) + .join('/') + return `${host}${safePath}` + } catch (error: unknown) { + return '' + } +} + +/** + * Render an error for the log, preferring the raw message. + * + * The mix-fetch v1 Go layer surfaces failures as opaque strings such as + * `panic:todo: extract error message`, where the real reason is discarded + * inside the library. Keeping the message verbatim is what makes those + * reports attributable to a specific host. + */ +function describeError(error: unknown): string { + if (error instanceof Error) { + return error.name === 'Error' + ? error.message + : `${error.name}: ${error.message}` + } + return String(error) +} + /** * Initialize the NYM mixFetch client. Must be called before using mixFetch. * Safe to call multiple times - subsequent calls return the same promise. */ export async function initMixFetch(log: EdgeLog): Promise { if (mixFetchInitPromise == null) { - log('Initializing mixFetch...') + log.warn('Initializing mixFetch...') + const setupStart = Date.now() const pending = createMixFetch(mixFetchOptions) // The timeout below can abandon this setup while it is still in flight. // Deliberately do NOT tear it down on late completion: `createMixFetch` @@ -60,7 +120,9 @@ export async function initMixFetch(log: EdgeLog): Promise { }) mixFetchInitPromise = Promise.race([pending, timeout]) .then(mixFetchModule => { - log('mixFetch initialized successfully') + log.warn( + `mixFetch initialized successfully in ${Date.now() - setupStart}ms` + ) return mixFetchModule }) .catch(async error => { @@ -73,7 +135,11 @@ export async function initMixFetch(log: EdgeLog): Promise { // eslint-disable-next-line @typescript-eslint/no-dynamic-delete delete (window as any).__mixFetchGlobal mixFetchInitPromise = null - log.error('mixFetch initialization failed:', error) + log.error( + `mixFetch initialization failed after ${ + Date.now() - setupStart + }ms: ${describeError(error)}` + ) throw error }) .finally(() => { @@ -83,3 +149,56 @@ export async function initMixFetch(log: EdgeLog): Promise { const mixFetchModule = await mixFetchInitPromise return mixFetchModule.mixFetch } + +/** + * Perform a single request over the NYM mixnet, logging its lifecycle. + * + * Every request writes a `start` line before it goes out and exactly one + * terminal line when it settles. A request that produces a `start` with no + * terminal line is one that never came back, which is the shape we cannot + * currently attribute to a host, and the reason this instrumentation exists. + * + * These go out at `warn` rather than `info` deliberately. The app configures + * the core with `defaultLogLevel: 'warn'`, so `info` is dropped unless the + * user has turned on Verbose Logging, and a QA log export would arrive with + * none of this in it. NYM is opt-in and low volume, so the extra lines only + * appear for the users whose reports we are trying to diagnose. + */ +export async function nymFetch( + uri: string, + opts: EdgeFetchOptions, + log: EdgeLog +): Promise { + const mixFetch = await initMixFetch(log) + + const id = ++requestCounter + const target = describeUri(uri) + const method = opts.method ?? 'GET' + const label = `mixFetch #${id} ${method} ${target}` + + const start = Date.now() + log.warn(`${label} start (${++inFlightCount} in flight)`) + try { + const response = await mixFetch( + uri, + { + ...opts, + mode: 'unsafe-ignore-cors' as RequestMode + }, + mixFetchOptions + ) + log.warn( + `${label} -> ${response.status} in ${ + Date.now() - start + }ms (${--inFlightCount} in flight)` + ) + return response + } catch (error: unknown) { + log.error( + `${label} failed after ${ + Date.now() - start + }ms (${--inFlightCount} in flight): ${describeError(error)}` + ) + throw error + } +} From c023d0ac1ba152b547edbc8b1514463ca4749154 Mon Sep 17 00:00:00 2001 From: Jonathan Tzeng Date: Mon, 20 Jul 2026 16:24:37 -0700 Subject: [PATCH 2/2] Bound NYM mixnet request concurrency and timeout Measured on a throttled Android emulator with the request logging from the previous commit: a single Avalanche wallet opens 12 concurrent mixnet requests during one sync. mix-fetch v1 has a history of serving one request per host at a time, which this module used to work around with a per-host queue removed in 5916d9d2 on the understanding that 1.4.2 had fixed it. Cap the mixnet at 6 concurrent requests overall and 2 per host, queueing the rest. Measured before and after on the same emulator against the live mixnet: peak in-flight drops from 12 to 6, per-request latency is unchanged (p50 2666ms vs 2669ms), and every request still settles. Also drop the per-request timeout from 300s to 60s. Healthy requests measure 2-4 seconds, so five minutes only ever meant that a request the mixnet never answered pinned its caller for five minutes. On the send screen that is the 'Calculating Fee' spinner that QA reports as an infinite hang. Neither change touches the request logging, which is still needed to attribute the remaining NYM-internal failure. --- CHANGELOG.md | 2 + src/util/nym.ts | 191 ++++++++++++++++++++++++++++++++++++++++++++---- 2 files changed, 177 insertions(+), 16 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index afcf19620..181dd5068 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,8 @@ ## Unreleased - added: Log the lifecycle of every NYM mixnet request (method, host, path, duration, HTTP status or error, and in-flight count), plus mixFetch setup timing. A request that logs a start with no terminal line identifies the host whose request never returned, which the previous logging could not attribute. These log at `warn` so they survive the default `warn` log level and appear in a log export without the user first enabling verbose logging. +- changed: Bound NYM mixnet requests to 6 concurrent overall and 2 per host. A single Avalanche wallet was measured opening 12 concurrent mixnet requests during one sync, and a full wallet list multiplies that; mix-fetch v1 has a history of serving one request per host at a time. +- fixed: Reduce the NYM per-request timeout from 300 seconds to 60. At five minutes, a request the mixnet never answered held the send screen on "Calculating Fee" long enough to read as a permanent hang rather than an error. ## 2.47.1 (2026-07-17) diff --git a/src/util/nym.ts b/src/util/nym.ts index 3cc657d3f..a9602a69d 100644 --- a/src/util/nym.ts +++ b/src/util/nym.ts @@ -18,10 +18,40 @@ export const mixFetchOptions: SetupMixFetchOps = { '5x6q9UfVHs5AohKMUqeivj7a556kVVy7QwoKige8xHxh.6CFoB3kJaDbYz6oafPJxNxNjzahpT2NtgtytcSyN9EvF@5rXcNe2a44vXisK3uqLHCzpzvEwcnsijDMU7hg4fcYk8', forceTls: true, // force WSS mixFetchOverride: { - requestTimeoutMs: 300000 + // A healthy mixnet request measures 2-4 seconds. The previous 300000 (5 + // minutes) meant any request the mixnet never answered held its caller for + // five minutes, which on the send screen reads as a permanently stuck + // "Calculating Fee" spinner rather than an error. + requestTimeoutMs: 60000 } } +/** + * Ceilings on how many requests are in the mixnet at once. + * + * mix-fetch v1 historically served one request per host at a time, which this + * module used to work around with a per-host queue. That queue was removed in + * 5916d9d2 on the understanding that 1.4.2 had fixed the limitation. Measured + * on an Android emulator, a single Avalanche wallet still opens 12 concurrent + * requests during one sync, and a wallet list the size of a real user's + * multiplies that. Bounding it keeps the tunnel inside a regime we have + * actually observed working, at a negligible cost given each request already + * takes seconds. + */ +const MAX_IN_FLIGHT_TOTAL = 6 +const MAX_IN_FLIGHT_PER_HOST = 2 + +/** + * How long a request will wait for a slot before going anyway. + * + * The ceilings above are smoothing, not an invariant worth stalling on. If + * every slot is held by a request that will not answer, an unbounded queue + * would add its own multi-minute delay on top of the per-request timeout and + * recreate exactly the stuck "Calculating Fee" this change exists to prevent. + * Past this deadline the request proceeds and the log says it did. + */ +const MAX_QUEUE_WAIT_MS = 10000 + /** * Budget for `createMixFetch` itself (client start + gateway handshake). * @@ -43,13 +73,102 @@ let inFlightCount = 0 // Distinguishes concurrent requests to the same host in the log. let requestCounter = 0 +// Requests waiting on a concurrency slot, oldest first. +const waiting: Array<() => void> = [] + +// In-flight count per host key, for the per-host ceiling. +const hostInFlight = new Map() + /** - * A path segment that is long and unbroken enough to be an identifier rather - * than a route: an address, a txid, a public key, or an API key. Real route - * segments in the endpoints we call (`ext`, `bc`, `C`, `rpc`, `v2`, `api`, - * `get_address_info`) are short, or contain separators, or both. + * The `host:port` a request will actually open, used to key the per-host + * ceiling. Falls back to the raw uri so an unparsable one still gets queued + * rather than bypassing the limit. */ -const IDENTIFIER_SEGMENT = /^(0x)?[0-9a-zA-Z]{20,}$/ +function getHostKey(uri: string): string { + try { + const url = new URL(uri) + const port = + url.port !== '' ? url.port : url.protocol === 'https:' ? '443' : '80' + return `${url.hostname}:${port}` + } catch (error: unknown) { + return uri + } +} + +function hasSlot(hostKey: string): boolean { + return ( + inFlightCount < MAX_IN_FLIGHT_TOTAL && + (hostInFlight.get(hostKey) ?? 0) < MAX_IN_FLIGHT_PER_HOST + ) +} + +/** + * Wait until this request is allowed into the mixnet, then reserve its slot. + * + * Returns true when the slot was granted by the ceilings, false when the + * deadline elapsed first and the request is proceeding regardless. The slot is + * reserved either way, so the counters stay honest. + */ +async function acquireSlot(hostKey: string): Promise { + const deadline = Date.now() + MAX_QUEUE_WAIT_MS + let granted = true + + while (!hasSlot(hostKey)) { + const remaining = deadline - Date.now() + if (remaining <= 0) { + granted = false + break + } + let timer: ReturnType | undefined + let wake: () => void = () => {} + await new Promise(resolve => { + wake = resolve + waiting.push(resolve) + timer = setTimeout(resolve, remaining) + }) + clearTimeout(timer) + // Drop our own resolver. `releaseSlot` drains the whole array, so this + // only matters when the deadline fired instead: without it, a stretch + // where nothing settles (exactly the case being diagnosed) would grow + // `waiting` without bound, since nothing else ever clears it. + const index = waiting.indexOf(wake) + if (index !== -1) waiting.splice(index, 1) + } + + inFlightCount += 1 + hostInFlight.set(hostKey, (hostInFlight.get(hostKey) ?? 0) + 1) + return granted +} + +/** + * Release this request's slot and wake everyone waiting. + * + * Every waiter re-checks its own host ceiling in `acquireSlot`, so waking all + * of them is correct: the ones still blocked simply queue again. Waking only + * the head would stall the queue whenever the head is blocked on a busy host + * while a slot for some other host just came free. + */ +function releaseSlot(hostKey: string): void { + inFlightCount -= 1 + const remaining = (hostInFlight.get(hostKey) ?? 1) - 1 + if (remaining <= 0) hostInFlight.delete(hostKey) + else hostInFlight.set(hostKey, remaining) + + const woken = waiting.splice(0, waiting.length) + for (const wake of woken) wake() +} + +/** + * A path segment long enough to be an identifier rather than a route: an + * address, a txid, a public key, or an API key. + * + * Length is what separates the two, not character set. Route segments in the + * endpoints we call are short (`ext`, `bc`, `C`, `rpc`, `v2`, `api`, the + * 16-character `get_address_info`), while identifiers run 26 characters and up. + * The separator classes matter: hyphens for UUIDs, a colon for cashaddr-style + * `prefix:address`, underscores and dots for the rest. + */ +const IDENTIFIER_SEGMENT = /^[0-9a-zA-Z][0-9a-zA-Z._:-]{19,}$/ /** * Reduce a request URI to the part that is safe to write to a user's log. @@ -77,21 +196,41 @@ function describeUri(uri: string): string { } } +/** + * Reduce any URL embedded in free text the same way `describeUri` reduces the + * request target. + * + * Error messages from the fetch and Go layers routinely quote the whole + * request URL (`Post "https://host/tx/?apikey=...": context deadline + * exceeded`). Running them through the same reducer keeps one rule for what + * may reach a support log, so an identifier masked in the request label cannot + * reappear intact in the error text on the very same line. + */ +function redactUrlsInText(text: string): string { + return text.replace(/https?:\/\/[^\s"'<>]+/g, url => { + // Trailing punctuation belongs to the sentence, not the URL. + const trimmed = url.replace(/[.,:;!?)\]}]+$/, '') + return describeUri(trimmed) + url.slice(trimmed.length) + }) +} + /** * Render an error for the log, preferring the raw message. * * The mix-fetch v1 Go layer surfaces failures as opaque strings such as * `panic:todo: extract error message`, where the real reason is discarded * inside the library. Keeping the message verbatim is what makes those - * reports attributable to a specific host. + * reports attributable to a specific host, so the text is preserved apart + * from query strings, which are the part that carries credentials. */ function describeError(error: unknown): string { - if (error instanceof Error) { - return error.name === 'Error' - ? error.message - : `${error.name}: ${error.message}` - } - return String(error) + const text = + error instanceof Error + ? error.name === 'Error' + ? error.message + : `${error.name}: ${error.message}` + : String(error) + return redactUrlsInText(text) } /** @@ -176,8 +315,26 @@ export async function nymFetch( const method = opts.method ?? 'GET' const label = `mixFetch #${id} ${method} ${target}` + const hostKey = getHostKey(uri) + const queuedAt = Date.now() + const granted = await acquireSlot(hostKey) + const queuedMs = Date.now() - queuedAt + const start = Date.now() - log.warn(`${label} start (${++inFlightCount} in flight)`) + const queueNote = + queuedMs === 0 + ? '' + : granted + ? `, queued ${queuedMs}ms` + : `, queued ${queuedMs}ms then went over the limit` + log.warn(`${label} start (${inFlightCount} in flight${queueNote})`) + let released = false + const release = (): void => { + if (released) return + released = true + releaseSlot(hostKey) + } + try { const response = await mixFetch( uri, @@ -187,17 +344,19 @@ export async function nymFetch( }, mixFetchOptions ) + release() log.warn( `${label} -> ${response.status} in ${ Date.now() - start - }ms (${--inFlightCount} in flight)` + }ms (${inFlightCount} in flight)` ) return response } catch (error: unknown) { + release() log.error( `${label} failed after ${ Date.now() - start - }ms (${--inFlightCount} in flight): ${describeError(error)}` + }ms (${inFlightCount} in flight): ${describeError(error)}` ) throw error }