From 6bc7a8dc1cc8beea23e4874543dcc1498d0d1fd0 Mon Sep 17 00:00:00 2001 From: J-Dog Date: Sat, 29 Aug 2026 09:51:56 -0700 Subject: [PATCH 1/7] fix(decoder): RPC faults keep their identity, and tuning env vars go through the shared validator Review round 2026-08-29 (xchain-platform board 161 -> 0). --- src/BlockchainConnector.js | 262 ++++++------------ src/XChainDecoder.js | 83 +++--- src/api.js | 18 ++ src/coins/index.js | 28 +- src/db.js | 32 ++- src/decoderMetrics.js | 18 +- .../blockchainConnectorReviewFixes.test.js | 122 ++++++++ test/unit/decoderLiveHeartbeat.test.js | 37 +++ test/unit/decoderTipStaleSurface.test.js | 42 +++ test/unit/rpcLookupFailure.test.js | 145 ++++++++++ test/unit/sql-quote-backslash-escapes.test.js | 133 +++++++++ 11 files changed, 703 insertions(+), 217 deletions(-) create mode 100644 test/unit/sql-quote-backslash-escapes.test.js diff --git a/src/BlockchainConnector.js b/src/BlockchainConnector.js index 5259ae6..50ae228 100644 --- a/src/BlockchainConnector.js +++ b/src/BlockchainConnector.js @@ -305,7 +305,10 @@ class BlockchainConnector { for (const fallback of fallbacks) this.endpoints.push(normalizeEndpoint(fallback, port)) this.activeEndpointIndex = 0 this.connectionFailures = 0 - this.failoverThreshold = Math.max(1, parseInt(process.env.NODE_FAILOVER_THRESHOLD, 10) || 3) + // envInt, not parseInt: a unit-suffixed value ('5m') truncates to a wrong + // magnitude and a bare `VAR=` line yields NaN, both silently. Every RPC knob in + // this file validates and reports the same way. + this.failoverThreshold = envInt(process.env.NODE_FAILOVER_THRESHOLD, 3, 'NODE_FAILOVER_THRESHOLD') } // Active RPC base URL. A getter (not a stored string) so every retry loop @@ -365,131 +368,94 @@ class BlockchainConnector { if (delay > 0) await this.sleep(delay) } - async getNetworkInfo(){ + // The single retry-and-classify ladder for the block-path RPC methods. Seven of + // them carried a byte-identical copy of it, differing only in the payload and two + // log strings, while the eighth (getRawTransaction, which owns its own ladder for + // the -5 eviction and -429 queue-full cases) drifted away from them: a correction + // to what the node's failure modes ARE could land in one place and miss the rest. + // + // The retry semantics here are the seven copies' own, deliberately unchanged. Only + // ECONNABORTED retries; every other error is logged and rethrown at once with + // error.code, error.rpcCode and error.rpcMessage intact. Adding getRawTransaction's + // 5s-x10 queue-full ladder here would be a behaviour change, not a de-duplication: + // the decoder's wedge signal counts CONSECUTIVE fetch failures at one height + // (XChainDecoder._fetchErrorCount, STALL_FETCH_ATTEMPTS) and reaches its verdict in + // about a minute at the block loop's 3s sleep. At ~50s per in-call ladder the same + // twenty attempts take a quarter of an hour, so isStalled() and the container + // healthcheck would go blind for exactly the outage they exist to report. + // + // Exhaustion is the one behaviour correction: it now counts toward rpcErrors and + // carries the last sanitized cause, matching getRawTransaction. A node that + // black-holed every request timed out ten times and threw a bare sentence, leaving + // rpc_errors_total ("Node RPC errors seen since process start") flat throughout. + // + // `label` names the subject in the timeout and error logs; `resultLabel` and + // `exhausted` override the two messages whose wording differs per method. + async rpcCallWithTimeoutRetry(data, label, { resultLabel, exhausted } = {}){ let tries = 10 + let lastErrorSummary = null while (tries > 0) { try { - const data = { - jsonrpc: '2.0', - method: 'getnetworkinfo', - id: 1 - } - const response = await this.rpcPost(data) - return rpcResult(response, 'Error getting network info'); + return rpcResult(response, resultLabel || `Error getting ${label}`); } catch (error) { if (error.code === 'ECONNABORTED') { tries = tries - 1 - console.log("Getting timeout trying to get network info, trying again...") + console.log(`Getting timeout trying to get ${label}, trying again...`) + lastErrorSummary = sanitizeRpcError(error) await this.backoffOnTimeout() } else { this.rpcErrors++ - console.error('Error getting network info:', sanitizeRpcError(error)); + console.error(`Error getting ${label}:`, sanitizeRpcError(error)); throw error; } } } - throw new Error("There were problems getting network info.") + this.rpcErrors++ + const message = exhausted || `There were problems getting ${label}.` + throw new Error(lastErrorSummary ? `${message} ${lastErrorSummary}` : message) } - - async getBlockchainInfo(){ - let tries = 10 - - while (tries > 0) { - try { - const data = { - jsonrpc: '2.0', - method: 'getblockchaininfo', - id: 1 - } - - const response = await this.rpcPost(data) - return rpcResult(response, 'Error getting blockchain info'); - } catch (error) { - if (error.code === 'ECONNABORTED') { - tries = tries - 1 - console.log("Getting timeout trying to get blockchain info, trying again...") - await this.backoffOnTimeout() - } else { - this.rpcErrors++ - console.error('Error getting blockchain info:', sanitizeRpcError(error)); - throw error; - } - } - } + async getNetworkInfo(){ + return await this.rpcCallWithTimeoutRetry({ + jsonrpc: '2.0', + method: 'getnetworkinfo', + id: 1 + }, 'network info') + } - throw new Error("There were problems getting blockchain info.") + async getBlockchainInfo(){ + return await this.rpcCallWithTimeoutRetry({ + jsonrpc: '2.0', + method: 'getblockchaininfo', + id: 1 + }, 'blockchain info') } async getBlockHash(blockindex) { - let tries = 10 - // getblockhash takes an integer height; a BigInt (BIGINT UNSIGNED columns decode as // BigInt) is never a valid JSON-RPC param and makes axios' JSON.stringify throw // "Do not know how to serialize a BigInt". Coerce defensively at the RPC boundary. blockindex = Number(blockindex) - while (tries > 0) { - try { - const data = { - jsonrpc: '2.0', - method: 'getblockhash', - params: [blockindex], - id: 1, - } - - const response = await this.rpcPost(data) - - return rpcResult(response, 'Error getting block hash'); - } catch (error) { - if (error.code === 'ECONNABORTED') { - tries = tries - 1 - console.log("Getting timeout trying to get block hash, trying again...") - await this.backoffOnTimeout() - } else { - this.rpcErrors++ - console.error('Error getting block hash:', sanitizeRpcError(error)); - throw error; - } - } - } - - throw new Error("There were problems getting block hash.") + return await this.rpcCallWithTimeoutRetry({ + jsonrpc: '2.0', + method: 'getblockhash', + params: [blockindex], + id: 1, + }, 'block hash') } async getBlockHeader(blockhash, hexFormat = true) { - let tries = 10 - - while (tries > 0) { - try { - const data = { - jsonrpc: '2.0', - method: 'getblockheader', - params: [blockhash, !hexFormat], - id: 1, - } - - const response = await this.rpcPost(data) - - return rpcResult(response, 'Error getting block header'); - } catch (error) { - if (error.code === 'ECONNABORTED') { - tries = tries - 1 - console.log("Getting timeout trying to get block header, trying again...") - await this.backoffOnTimeout() - } else { - this.rpcErrors++ - console.error('Error getting block header:', sanitizeRpcError(error)); - throw error; - } - } - } - - throw new Error("There were problems getting a block header. ") + return await this.rpcCallWithTimeoutRetry({ + jsonrpc: '2.0', + method: 'getblockheader', + params: [blockhash, !hexFormat], + id: 1, + }, 'block header', { exhausted: 'There were problems getting a block header. ' }) } // The RPC fetches below are deliberately OUTSIDE the try. A transport fault (a @@ -560,64 +526,20 @@ class BlockchainConnector { } async getBlockVerbose(blockhash) { - let tries = 10 - - while (tries > 0) { - try { - const data = { - jsonrpc: '2.0', - method: 'getblock', - params: [blockhash, true], - id: 1, - } - - const response = await this.rpcPost(data) - - return rpcResult(response, 'Error getting verbose block'); - } catch (error) { - if (error.code === 'ECONNABORTED') { - tries = tries - 1 - console.log("Getting timeout trying to get verbose block, trying again...") - await this.backoffOnTimeout() - } else { - this.rpcErrors++ - console.error('Error getting verbose block:', sanitizeRpcError(error)); - throw error; - } - } - } - - throw new Error("There were problems getting verbose block.") + return await this.rpcCallWithTimeoutRetry({ + jsonrpc: '2.0', + method: 'getblock', + params: [blockhash, true], + id: 1, + }, 'verbose block') } async getRawMempool(){ - let tries = 10 - - while (tries > 0) { - try { - const data = { - jsonrpc: '2.0', - method: 'getrawmempool', - id: 1 - } - - const response = await this.rpcPost(data) - - return rpcResult(response, 'Error getting raw mempool info'); - } catch (error) { - if (error.code === 'ECONNABORTED') { - tries = tries - 1 - console.log("Getting timeout trying to get raw mempool, trying again...") - await this.backoffOnTimeout() - } else { - this.rpcErrors++ - console.error('Error getting raw mempool:', sanitizeRpcError(error)); - throw error; - } - } - } - - throw new Error("There were problems getting raw mempool.") + return await this.rpcCallWithTimeoutRetry({ + jsonrpc: '2.0', + method: 'getrawmempool', + id: 1 + }, 'raw mempool', { resultLabel: 'Error getting raw mempool info' }) } async getRawTransaction(txid){ @@ -737,7 +659,11 @@ class BlockchainConnector { // connection drops) on a large mempool, each retried up to 10x. Requests // now run in order-preserving sub-batches; tune via DECODER_RPC_CONCURRENCY. async getRawTransactions(txIdArray){ - const concurrency = Math.max(1, parseInt(process.env.DECODER_RPC_CONCURRENCY, 10) || 50) + // envInt, not parseInt: 'DECODER_RPC_CONCURRENCY=100x' truncated to 100 sockets + // against the operator's node with no log line, which is the fan-out this bound + // exists to cap. Read per call, not cached, so a test (and an operator) can + // retune it without rebuilding the connector. + const concurrency = envInt(process.env.DECODER_RPC_CONCURRENCY, 50, 'DECODER_RPC_CONCURRENCY') const results = [] for (let i = 0; i < txIdArray.length; i += concurrency){ const slice = txIdArray.slice(i, i + concurrency) @@ -770,34 +696,12 @@ class BlockchainConnector { } async getBlock(blockhash, hexFormat=true) { - let tries = 10 - - while (tries > 0) { - try { - const data = { - jsonrpc: '2.0', - method: 'getblock', - params: [blockhash, !hexFormat], - id: 1, - } - - const response = await this.rpcPost(data) - - return rpcResult(response, 'Error getting block hex'); - } catch (error) { - if (error.code === 'ECONNABORTED') { - tries = tries - 1 - console.log("Getting timeout trying to get block, trying again...") - await this.backoffOnTimeout() - } else { - this.rpcErrors++ - console.error('Error getting block:', sanitizeRpcError(error)); - throw error; - } - } - } - - throw new Error("There were problems getting block.") + return await this.rpcCallWithTimeoutRetry({ + jsonrpc: '2.0', + method: 'getblock', + params: [blockhash, !hexFormat], + id: 1, + }, 'block', { resultLabel: 'Error getting block hex' }) } } diff --git a/src/XChainDecoder.js b/src/XChainDecoder.js index 4df6171..9b1b51a 100644 --- a/src/XChainDecoder.js +++ b/src/XChainDecoder.js @@ -726,31 +726,38 @@ class XChainDecoder { // so a block is only ever committed from fully-resolved lookups. The prevout of a // confirmed tx always exists on a txindex node, so an empty RPC result is a // lookup failure too, never "absent". + let outputRawTransaction try { - let outputRawTransaction = await this.connector.getRawTransaction(txId) + outputRawTransaction = await this.connector.getRawTransaction(txId) if (!outputRawTransaction){ throw new Error(`empty getrawtransaction result for confirmed prevout tx ${txId}`) } - // MUST parse through transactionFromHex (strips the LTC MWEB marker+flag), not - // bitcoin.Transaction.fromHex. A funding/prevout tx on Litecoin can carry the - // MWEB flag (0x08/0x09); vanilla strict parsing throws a deterministic UInt64 - // range error, which the catch below then mis-tags as rpcLookupFailure=true. - // The block loop treats rpcLookupFailure as transient node trouble and retries - // the block FOREVER, so a deterministic content-parse error would wedge every - // LTC decoder instance permanently. transactionFromHex is the same parser the - // block path uses; for BTC/DOGE and non-flagged txs it is a plain parse. - outputTransaction = this.xchainBlockDecoder.transactionFromHex(outputRawTransaction) - // Publish the FIRST-HOP tx here, before the P2SH/P2WSH walk-back below can - // reassign `output`. The walk-back fetches the commit's own funder, a - // different transaction; handing that to the fee resolver would attribute - // another tx's outputs into this action's reserved FUNDING_VOUT_BASE domain. - if (capture) capture.sourceTransaction = outputTransaction } catch (err){ this.rpcErrors++ console.error(`getSourceFromOutput: failed to fetch tx ${txId} (output ${outputIndex}): `, err) err.rpcLookupFailure = true throw err } + // Decode OUTSIDE the tagged try. getRawTransaction either yields a whole + // JSON-decoded hex string or fails, so a wire-decode throw here is deterministic + // CONTENT, identical on every instance, not a transport fault. Tagging it + // rpcLookupFailure routed it to the block loop's UNBOUNDED height retry and wedged + // the decoder at that height forever; untagged it reaches the retry-then-quarantine + // ladder (TX_PARSE_MAX_RETRIES), which is parity-safe exactly because the fault is + // deterministic. start() refuses to run a Dogecoin decoder whose BigInt-safe + // bufferutils reader is inactive for the same reason: that is the one decode fault + // that would differ between instances. + // MUST parse through transactionFromHex (strips the LTC MWEB marker+flag), not + // bitcoin.Transaction.fromHex: a Litecoin funding/prevout tx can carry the MWEB + // flag (0x08/0x09) and vanilla strict parsing throws a UInt64 range error on it. + // transactionFromHex is the same parser the block path uses; for BTC/DOGE and + // non-flagged txs it is a plain parse. + outputTransaction = this.xchainBlockDecoder.transactionFromHex(outputRawTransaction) + // Publish the FIRST-HOP tx here, before the P2SH/P2WSH walk-back below can + // reassign `output`. The walk-back fetches the commit's own funder, a + // different transaction; handing that to the fee resolver would attribute + // another tx's outputs into this action's reserved FUNDING_VOUT_BASE domain. + if (capture) capture.sourceTransaction = outputTransaction // An out-of-range output index is deterministic content (the same on every // instance), so it may still resolve to a null source below. output = outputTransaction.outs[outputIndex] @@ -777,22 +784,23 @@ class XChainDecoder { if (isP2sh || isP2wsh){ let prevOutputIndex = outputTransaction.ins[0].index let prevTxHash = util.uint8ArrayToHex(Buffer.from(outputTransaction.ins[0].hash).reverse()) - // Same fail-loud contract as the first fetch: tag the failure so the + // Same fail-loud contract as the first fetch: tag the FETCH failure so the // block loop retries the block instead of quarantining the tx. - let prevTransaction + let prevRawTransaction try { - let prevRawTransaction = await this.connector.getRawTransaction(prevTxHash) + prevRawTransaction = await this.connector.getRawTransaction(prevTxHash) if (!prevRawTransaction){ throw new Error(`empty getrawtransaction result for confirmed commit-funding tx ${prevTxHash}`) } - // transactionFromHex (MWEB-flag-safe), not bitcoin.Transaction.fromHex; see above. - prevTransaction = this.xchainBlockDecoder.transactionFromHex(prevRawTransaction) } catch (err){ this.rpcErrors++ console.error(`getSourceFromOutput: failed to fetch commit-funding tx ${prevTxHash}: `, err) err.rpcLookupFailure = true throw err } + // Decode outside the tagged try; see the first fetch above. + // transactionFromHex (MWEB-flag-safe), not bitcoin.Transaction.fromHex. + let prevTransaction = this.xchainBlockDecoder.transactionFromHex(prevRawTransaction) output = prevTransaction.outs[prevOutputIndex] } @@ -947,20 +955,21 @@ class XChainDecoder { if (!commitTransaction.ins || commitTransaction.ins.length === 0) return null const prevTxHash = util.uint8ArrayToHex(Buffer.from(commitTransaction.ins[0].hash).reverse()) const prevOutputIndex = commitTransaction.ins[0].index - let prevTransaction + let prevRawTransaction try { - const prevRawTransaction = await this.connector.getRawTransaction(prevTxHash) + prevRawTransaction = await this.connector.getRawTransaction(prevTxHash) if (!prevRawTransaction){ throw new Error(`empty getrawtransaction result for confirmed commit-funding tx ${prevTxHash}`) } - // transactionFromHex (MWEB-flag-safe), not bitcoin.Transaction.fromHex. - prevTransaction = this.xchainBlockDecoder.transactionFromHex(prevRawTransaction) } catch (err){ this.rpcErrors++ console.error(`getEnvelopeSourceFromCommit: failed to fetch commit-funding tx ${prevTxHash}: `, err) err.rpcLookupFailure = true throw err } + // Decode outside the tagged try; see getSourceFromOutput. + // transactionFromHex (MWEB-flag-safe), not bitcoin.Transaction.fromHex. + const prevTransaction = this.xchainBlockDecoder.transactionFromHex(prevRawTransaction) const output = prevTransaction.outs[prevOutputIndex] if (output == null) return null let source = null @@ -979,18 +988,20 @@ class XChainDecoder { // confirmed-prevout fetch: the commit of a confirmed reveal always exists // on a txindex node, so an empty result is a lookup failure, never absence. async fetchEnvelopeCommitTransaction(commitTxId){ + let rawTransaction try { - const rawTransaction = await this.connector.getRawTransaction(commitTxId) + rawTransaction = await this.connector.getRawTransaction(commitTxId) if (!rawTransaction){ throw new Error(`empty getrawtransaction result for confirmed envelope commit tx ${commitTxId}`) } - return this.xchainBlockDecoder.transactionFromHex(rawTransaction) } catch (err){ this.rpcErrors++ console.error(`fetchEnvelopeCommitTransaction: failed to fetch commit tx ${commitTxId}: `, err) err.rpcLookupFailure = true throw err } + // Decode outside the tagged try; see getSourceFromOutput. + return this.xchainBlockDecoder.transactionFromHex(rawTransaction) } // For a P2SH/P2WSH reveal, the native-coin fee output lives on the funding (commit) transaction: @@ -1012,19 +1023,21 @@ class XChainDecoder { // parsed, so the fetch below is the fallback for a caller that has none. let fundingTx = prefetchedFundingTx if (!fundingTx){ + let fundingTxHex try { - let fundingTxHex = await this.connector.getRawTransaction(fundingTxId) + fundingTxHex = await this.connector.getRawTransaction(fundingTxId) if (!fundingTxHex){ throw new Error(`empty getrawtransaction result for confirmed funding tx ${fundingTxId}`) } - // transactionFromHex (MWEB-flag-safe), not bitcoin.Transaction.fromHex; see getSourceFromOutput. - fundingTx = this.xchainBlockDecoder.transactionFromHex(fundingTxHex) } catch (err){ this.rpcErrors++ console.error(`findFundingFeeOutputs: failed to fetch funding tx ${fundingTxId}:`, err.message) err.rpcLookupFailure = true throw err } + // Decode outside the tagged try; see getSourceFromOutput. + // transactionFromHex (MWEB-flag-safe), not bitcoin.Transaction.fromHex. + fundingTx = this.xchainBlockDecoder.transactionFromHex(fundingTxHex) } for (let vout = 0; vout < fundingTx.outs.length; vout++){ let output = fundingTx.outs[vout] @@ -2032,11 +2045,19 @@ class XChainDecoder { // by XChainBlockDecoder), so this can only fire if that module regresses or a stray // bitcoinjs-lib copy shadows the patched one; keep the backstop so any such // regression is loud at startup rather than a mid-operation fleet halt. + // Refuse to start rather than warn. A prevout wire-decode fault now reaches the + // retry-then-quarantine ladder instead of the unbounded rpcLookupFailure retry + // (getSourceFromOutput), and quarantine is parity-safe only for a fault that is + // the SAME on every instance. An inactive patch is ENVIRONMENT-dependent: this + // instance would quarantine and skip a DOGE transaction every correctly patched + // instance decodes, committing instance-dependent block contents. Same + // util.throwError contract as the database checks below, so api.js start() and + // health() report it. if (this.xchainBlockDecoder && this.xchainBlockDecoder.coin === 'dogecoin' && !bigIntBufferutilsActive()){ - console.error('CRITICAL: bitcoinjs-lib bufferutils BigInt-safe 64-bit reader is NOT active on a ' + + util.throwError(new Error('CRITICAL: bitcoinjs-lib bufferutils BigInt-safe 64-bit reader is NOT active on a ' + 'Dogecoin decoder. A DOGE output > 2^53-1 sat (~90.07M DOGE) will throw during block decode ' + 'and wedge this decoder permanently. src/applyBufferutilsPatch.js should have applied it ' + - 'in-process; investigate before running on mainnet.') + 'in-process; investigate before running on mainnet.')) } let dbStatus = await this.db.createDatabase(); diff --git a/src/api.js b/src/api.js index ea0c722..845082a 100644 --- a/src/api.js +++ b/src/api.js @@ -102,6 +102,21 @@ function registerLiveRoute(app, decoder, isDecoderRunning){ // and /live answered 200 forever. GATES health, unlike node_height_stale // below: a dead loop is exactly the wedge a restart does fix. const pollSilent = typeof decoder.isPollSilent === 'function' ? decoder.isPollSilent() : false + // Latent REORG_HALT marker, reported on the one surface the monitor and the + // container healthcheck actually poll. /status and the JSON-RPC health method + // already carry it, and neither is polled, so a decoder carrying a durable halt + // row rendered fully green everywhere an operator looks. TTL-cached inside + // checkReorgHalt (60s) with concurrent probes collapsed, so a healthcheck burst + // costs at most one DB query per minute. + // + // Deliberately NOT in the healthy gate below, for the reason given at /status + // and the health method: the marker survives restarts and is cleared only by a + // resync, while the halted decoder keeps parsing forward, so gating would make + // autoheal restart-loop a service that is doing useful work and fix nothing. + let reorgHalt = { halted: false, reason: null, at: null } + if (dbOk && typeof decoder.checkReorgHalt === 'function'){ + try { reorgHalt = await decoder.checkReorgHalt() } catch (_) {} + } const syncStatus = decoder.getSyncStatus() const healthy = decoderRunning && dbOk && !stalled && !pollSilent res.status(healthy ? 200 : 503).json({ @@ -111,6 +126,9 @@ function registerLiveRoute(app, decoder, isDecoderRunning){ stalled, poll_silent: pollSilent, last_poll_at: decoder.lastPollAt || null, + reorg_halted: reorgHalt.halted === true, + reorg_halt_reason: reorgHalt.reason || null, + reorg_halted_at: reorgHalt.at || null, // A frozen node tip, reported but deliberately NOT gating. isStalled() // returns false while the tip is stale on purpose: restarting the container // cannot fix an upstream node outage, and gating on it re-opens the diff --git a/src/coins/index.js b/src/coins/index.js index 93325ea..0963b23 100644 --- a/src/coins/index.js +++ b/src/coins/index.js @@ -369,21 +369,39 @@ function verifyConsensusPin(network){ // Per-coin cross-chain confirmation thresholds via the hub's standard // three-tier idiom: env XCHAIN_CONFIRMATIONS_ -> p2pConfig -> per-coin -// default. On mainnet an override may only RAISE the depth (CF-1): +// default. On mainnet AND testnet an override may only RAISE the depth (CF-1): // the defaults are a consensus-safety floor, and a single validator running a // lowered depth would co-sign source actions the rest of the federation still -// considers reorg-able. testnet/regtest keep the full override for drills. +// considers reorg-able. Only regtest, the single-operator drill network, keeps +// the full override. +// +// testnet is consensus-real for this purpose: a multi-operator federation run by +// outside operators (the validator runbook hands them HUB_NETWORK=testnet) with an +// ARMED consensus pin, so the same fork risk applies and a clean pin must not read +// as covering this depth. Every sibling seam gates on regtest alone for that reason: +// resolveFeeDestination above, XChainHub._oracleMaxAgeSeconds, +// XchainPriceSource.pinOffRegtest and CapabilitySnapshot._resolveReorgBuffer. +// +// Raising stays legal on every network because raising is unilaterally +// conservative: the validator simply waits longer. Only lowering forks co-signing. +// The floor also keeps a hub from ever attesting an anchor SHALLOWER than the BTC +// indexer's reward-mint gate will accept, which is frozen at the same per-coin +// default (ANCHOR_REWARD_DOGE_MIN_CONFIRMATIONS in anchor_reward_activation.js). +// The mint gate is NOT this knob and never reads it: it is a ledger input, this is +// local hub trust policy, and on regtest the two may legitimately differ. function resolveConfirmations(cfg, network){ cfg = cfg || {}; const out = {}; + const floored = (network === 'mainnet' || network === 'testnet'); for(const tick of ALLOWED_COINS){ const key = 'XCHAIN_CONFIRMATIONS_' + tick; const def = DEFAULT_CONFIRMATIONS[tick]; let val = parseInt(process.env[key], 10) || parseInt(cfg[key], 10) || def; if(!Number.isFinite(val) || val <= 0) val = def; - if(network === 'mainnet' && val < def){ - console.warn('[coins] ' + key + '=' + val + ' is below the mainnet floor ' + def + - '; clamping to ' + def + ' (confirmation overrides may only raise the depth on mainnet)'); + if(floored && val < def){ + console.warn('[coins] ' + key + '=' + val + ' is below the ' + network + ' floor ' + def + + '; clamping to ' + def + ' (confirmation overrides may only raise the depth on ' + + 'mainnet and testnet; regtest keeps the full override)'); val = def; } out[tick] = val; diff --git a/src/db.js b/src/db.js index 3f1fc89..49bf14a 100644 --- a/src/db.js +++ b/src/db.js @@ -46,6 +46,32 @@ function resolveQueryTimeout(raw, defaultMs = DEFAULT_QUERY_TIMEOUT_MS) { return parsed } +// True when str[i] opens a backslash escape inside the currently open quoted span. +// +// MariaDB/MySQL honour `\` inside `'` and `"` string literals by default, so a +// `\'` does NOT close the literal. Every quote walker below must consult this helper +// instead of closing a span on the next matching quote: a span closed at the `\'` +// desyncs the scan from the statements the server would run. `INSERT ... VALUES +// ('it\'s fine'); DROP TABLE balances;` then re-opens at the literal's real closing +// quote and swallows the `;` and the DROP into one chunk whose first keyword is +// INSERT - invisible to the ^-anchored destructive checks in +// _destructiveAutoStatement, which would score the file auto-eligible. +// +// Backtick spans are excluded: a backslash inside an identifier quote is a literal +// character there, so consuming the next char would desync in the other direction. +// A trailing lone backslash opens nothing, so no walker indexes past end-of-input. +// +// Module-level, not a method: hasUnquotedHash is deliberately a local closure because +// runMigrations' callers build partial `this` objects, and a prototype hop would break +// the guard on those (see the comment at that closure). +// +// Holds only while sql_mode omits NO_BACKSLASH_ESCAPES. Nothing in this tree sets +// sql_mode and the pool params below set none; if that ever changes, every caller of +// this helper must be revisited. Kept byte-for-byte in sync with xchain-indexer/src/db.js. +function opensBackslashEscape(str, i, quote){ + return str[i] === '\\' && quote !== '`' && i + 1 < str.length; +} + class Database { constructor(host, port, dbName, user, pass){ if (!DB_NAME_REGEX.test(dbName)) { @@ -714,6 +740,7 @@ class Database { for(let i = 0; i < s.length; i++){ const c = s[i]; if(q){ + if(opensBackslashEscape(s, i, q)){ i++; continue; } if(c === q){ if(s[i + 1] === q){ i++; } else { q = null; } @@ -860,6 +887,7 @@ class Database { for(; i < stmt.length; i++){ const ch = stmt[i]; if(quote){ + if(opensBackslashEscape(stmt, i, quote)){ i++; continue; } if(ch === quote){ if(stmt[i + 1] === quote){ i++; } // doubled-quote escape else { quote = null; } @@ -915,6 +943,7 @@ class Database { const ch = sql[i]; if(quote){ out += ch; + if(opensBackslashEscape(sql, i, quote)){ out += sql[++i]; continue; } if(ch === quote){ if(sql[i + 1] === quote){ out += sql[++i]; } else { quote = null; } @@ -946,7 +975,7 @@ class Database { // ship, and _destructiveAutoStatement ends up classifying fragments rather than // real statements. `--` and `#` line comments are stripped first (same rule as // the callers used); the quote model matches stripSqlLineComments exactly - // (single/double-quote and backtick spans, doubled quotes treated as escapes). + // (single/double-quote and backtick spans, doubled-quote and backslash escapes). // Returns trimmed, non-empty statements. Mirrors xchain-indexer/src/db.js. splitSqlStatements(sql){ const stripped = this.stripSqlLineComments(sql); @@ -957,6 +986,7 @@ class Database { const ch = stripped[i]; if(quote){ current += ch; + if(opensBackslashEscape(stripped, i, quote)){ current += stripped[++i]; continue; } if(ch === quote){ if(stripped[i + 1] === quote){ current += stripped[++i]; } else { quote = null; } diff --git a/src/decoderMetrics.js b/src/decoderMetrics.js index 4b27b06..4d70e55 100644 --- a/src/decoderMetrics.js +++ b/src/decoderMetrics.js @@ -37,7 +37,9 @@ const DECODER_GAUGES = [ ['last_block_advance_timestamp_seconds', 'Unix time of the last forward block advance'], ['node_height_stale', '1 when the cached node tip is frozen (two or more consecutive tip polls failed)'], ['synced', '1 when the decoder is caught up to a fresh node tip'], - ['stalled', '1 when the block loop is wedged (the /live liveness signal)'], + ['stalled', '1 when the block loop is wedged on one height (/live gates on poll_silent too)'], + ['poll_silent', '1 when the block loop has stopped ITERATING; gates /live health beside stalled'], + ['last_poll_timestamp_seconds', 'Unix time of the last block-loop iteration, whether or not a block arrived'], ['last_reorg_depth', 'Blocks rolled back by the most recent reorg'] ]; @@ -92,6 +94,20 @@ function registerDecoderMetrics(registry, decoder) { if (typeof decoder.isSynced === 'function') gauges.synced.set({}, decoder.isSynced() ? 1 : 0); if (typeof decoder.isStalled === 'function') gauges.stalled.set({}, decoder.isStalled() ? 1 : 0); + // The dead-loop signal `stalled` is structurally blind to: isStalled() reports + // chain progress, which a caught-up decoder makes none of while perfectly + // healthy, so a loop that dies while caught up leaves stalled 0 forever. /live + // gates health on this one alongside stalled (api.js registerLiveRoute); a + // metrics-only deployment saw neither until now. Boolean always emits, matching + // isPollSilent()'s own "0 means not silent" answer before the first iteration; + // the timestamp stays absent until then, since 0 would read as 1970. + if (typeof decoder.isPollSilent === 'function') { + gauges.poll_silent.set({}, decoder.isPollSilent() ? 1 : 0); + } + if (decoder.lastPollAt > 0) { + setIf(gauges.last_poll_timestamp_seconds, decoder.lastPollAt / 1000); + } + // setMonotonic, not inc: these mirror lifetime counters the decoder already // keeps, and a re-read must not double-count what the last scrape saw. const rpcErrors = (decoder.rpcErrors || 0) + ((decoder.connector && decoder.connector.rpcErrors) || 0); diff --git a/test/unit/blockchainConnectorReviewFixes.test.js b/test/unit/blockchainConnectorReviewFixes.test.js index 502e973..74a72d3 100644 --- a/test/unit/blockchainConnectorReviewFixes.test.js +++ b/test/unit/blockchainConnectorReviewFixes.test.js @@ -226,4 +226,126 @@ describe('BlockchainConnector RPC error accounting and reporting', () => { assert.strictEqual(warnStub.callCount, 0) }) }) + + describe('the block-path RPC ladder is one implementation', () => { + // Seven methods each carried a byte-identical retry-and-classify block while + // getRawTransaction's classifier grew apart from them, so a correction to what + // the node's failure modes ARE could land in one copy and miss six. + const LADDER_METHODS = [ + ['getNetworkInfo', [], 'getnetworkinfo'], + ['getBlockchainInfo', [], 'getblockchaininfo'], + ['getBlockHash', [0], 'getblockhash'], + ['getBlockHeader', ['aa'], 'getblockheader'], + ['getBlockVerbose', ['aa'], 'getblock'], + ['getRawMempool', [], 'getrawmempool'], + ['getBlock', ['aa'], 'getblock'], + ] + + it('routes every block-path method through the shared ladder', async () => { + const seen = [] + connector.rpcCallWithTimeoutRetry = async (data) => { seen.push(data.method); return 'ok' } + + for (const [name, args] of LADDER_METHODS) { + assert.strictEqual(await connector[name](...args), 'ok', + `${name} must go through the shared ladder, not a private copy`) + } + assert.deepStrictEqual(seen, LADDER_METHODS.map(([, , rpc]) => rpc)) + }).timeout(5000) + + it('counts an exhausted timeout ladder toward rpc_errors_total and keeps the cause', async () => { + // A node that black-holes every request only ever raises ECONNABORTED, which + // the copies retried ten times and then rethrew as a bare sentence: the + // counter described as "Node RPC errors seen since process start" stayed 0 + // through a total outage, and the cause was discarded with it. + axiosStub.callsFake(async () => { + throw Object.assign(new Error('timeout of 30000ms exceeded'), { code: 'ECONNABORTED' }) + }) + + await assert.rejects( + () => connector.getBlockHash(0), + (err) => { + assert.ok(/There were problems getting block hash\./.test(err.message), + 'the per-method exhaustion message is unchanged') + assert.ok(/timeout of 30000ms exceeded/.test(err.message), + 'the last sanitized cause survives the exhaustion throw') + return true + } + ) + assert.strictEqual(axiosStub.callCount, 10, 'the 10-attempt timeout ladder is unchanged') + assert.strictEqual(connector.rpcErrors, 1, 'a black-holing node must move rpc_errors_total') + }).timeout(5000) + + it('keeps the block path failing FAST on a queue-full answer', async () => { + // Deliberately NOT getRawTransaction's 5s x10 queue-full ladder. The wedge + // signal counts consecutive fetch failures at one height + // (XChainDecoder._fetchErrorCount vs STALL_FETCH_ATTEMPTS) and reaches its + // verdict in about a minute at the block loop's 3s sleep; at ~50s per + // in-call ladder the same twenty attempts take a quarter of an hour. + axiosStub.rejects(Object.assign(new Error('Request failed with status code 500'), { + code: 'ERR_BAD_RESPONSE', + response: { status: 500, data: { error: { code: -429, message: 'Work queue depth exceeded' } } } + })) + + await assert.rejects(() => connector.getBlockHash(0), (err) => { + assert.strictEqual(err.rpcCode, -429, 'the node code reaches the caller intact') + return true + }) + assert.strictEqual(axiosStub.callCount, 1, 'no in-call retry for a non-timeout error') + assert.strictEqual(connector.rpcErrors, 1) + }).timeout(5000) + }) + + describe('every RPC knob in the file goes through envInt', () => { + // The two remaining env reads used bare parseInt behind a `|| default` guard, + // which absorbs NaN but not magnitude: NODE_FAILOVER_THRESHOLD=5m became 5 and + // DECODER_RPC_CONCURRENCY=100x became 100 sockets at the operator's node, both + // silently. They are knobs on the same seam as NODE_RPC_TIMEOUT and must + // validate and report identically. + let warnStub + + beforeEach(() => { + warnStub = sinon.stub(console, 'warn') + delete process.env.NODE_FAILOVER_THRESHOLD + delete process.env.DECODER_RPC_CONCURRENCY + }) + + afterEach(() => { + delete process.env.NODE_FAILOVER_THRESHOLD + delete process.env.DECODER_RPC_CONCURRENCY + }) + + it('NODE_FAILOVER_THRESHOLD=5m warns and keeps the default, not 5', () => { + process.env.NODE_FAILOVER_THRESHOLD = '5m' + const c = new BlockchainConnector('127.0.0.1', 8332, 'user', 'pass') + assert.strictEqual(c.failoverThreshold, 3) + assert.strictEqual(warnStub.callCount, 1, 'a mis-set knob must be visible in logs') + }) + + it('NODE_FAILOVER_THRESHOLD passes a valid value through silently', () => { + process.env.NODE_FAILOVER_THRESHOLD = '7' + const c = new BlockchainConnector('127.0.0.1', 8332, 'user', 'pass') + assert.strictEqual(c.failoverThreshold, 7) + assert.strictEqual(warnStub.callCount, 0) + }) + + it('DECODER_RPC_CONCURRENCY=100x warns and keeps the default, not 100 sockets', async () => { + process.env.DECODER_RPC_CONCURRENCY = '100x' + const c = new BlockchainConnector('127.0.0.1', 8332, 'user', 'pass') + + let inFlight = 0 + let peak = 0 + c.getRawTransaction = async () => { + inFlight++ + peak = Math.max(peak, inFlight) + await new Promise((r) => setImmediate(r)) + inFlight-- + return 'hex' + } + + const ids = Array.from({ length: 60 }, (_, i) => 'tx' + i) + assert.strictEqual((await c.getRawTransactions(ids)).length, 60) + assert.ok(peak <= 50, `sub-batch must stay at the default 50, saw ${peak}`) + assert.ok(warnStub.callCount >= 1, 'a mis-set knob must be visible in logs') + }).timeout(5000) + }) }) diff --git a/test/unit/decoderLiveHeartbeat.test.js b/test/unit/decoderLiveHeartbeat.test.js index 84d71b7..bfbcb99 100644 --- a/test/unit/decoderLiveHeartbeat.test.js +++ b/test/unit/decoderLiveHeartbeat.test.js @@ -143,6 +143,43 @@ describe('/live gates on the poll-loop heartbeat', function () { assert.strictEqual(res.body.poll_silent, false, 'the drain is crisp, not window-delayed'); }); + // The latent REORG_HALT marker was published on /status and the JSON-RPC health + // method, neither of which anything polls, and omitted from /live, which the + // monitor and the container healthcheck do poll. So the one surface that is read + // rendered a halted decoder fully green. + + it('reports a latent REORG_HALT marker on the surface that is actually polled', async function () { + const decoder = caughtUpDecoder(); + decoder.db.getReorgHaltMarker = async () => ({ halted: true, reason: 'delete failed at 149', at: '2026-08-20T04:00:00.000Z' }); + const res = await getLive(liveApp(decoder)); + assert.strictEqual(res.body.reorg_halted, true); + assert.strictEqual(res.body.reorg_halt_reason, 'delete failed at 149'); + assert.strictEqual(res.body.reorg_halted_at, '2026-08-20T04:00:00.000Z'); + }); + + it('still answers 200 while halted, so autoheal cannot restart-loop a resync case', async function () { + // The regression that matters. The marker survives restarts and is cleared only + // by a resync, and the halted decoder keeps parsing forward, so gating health on + // it would recycle a working container forever and fix nothing. + const decoder = caughtUpDecoder(); + decoder.db.getReorgHaltMarker = async () => ({ halted: true, reason: 'aborted rollback', at: null }); + const res = await getLive(liveApp(decoder)); + assert.strictEqual(res.status, 200); + assert.strictEqual(res.body.status, 'healthy'); + assert.strictEqual(res.body.reorg_halted, true); + }); + + it('reports the halt as a stable false, not an absent key, when there is no marker', async function () { + // An absent key and "not halted" must not look alike to the monitor: the rail + // reads a missing field as unknown, so a decoder that answers `false` is what + // lets it tell a healthy decoder from an unupgraded one. + const decoder = caughtUpDecoder(); + decoder.db.getReorgHaltMarker = async () => ({ halted: false, reason: null, at: null }); + const res = await getLive(liveApp(decoder)); + assert.strictEqual(res.body.reorg_halted, false); + assert.strictEqual(res.body.reorg_halt_reason, null); + }); + it('answers 503 when the DB ping fails, which the heartbeat must not mask', async function () { const decoder = caughtUpDecoder(); decoder.db = { ping: async () => { throw new Error('pool gone'); } }; diff --git a/test/unit/decoderTipStaleSurface.test.js b/test/unit/decoderTipStaleSurface.test.js index 39837b7..7e6f75c 100644 --- a/test/unit/decoderTipStaleSurface.test.js +++ b/test/unit/decoderTipStaleSurface.test.js @@ -218,6 +218,48 @@ describe('registerDecoderMetrics() feed-freshness gauges', function () { assert.match(body, /^xchain_decoder_node_height_stale 0$/m); }); + // Poll silence was the one /live gate the Prometheus surface did not carry, so an + // alert written against `stalled` -- whose help text called itself THE liveness + // signal -- read 0 through a parse loop that had died while caught up. + + it('exports the poll-silence gate /live health depends on', function () { + const registry = new Registry(); + const decoder = makeRunningDecoder(); + decoder.lastPollAt = Date.now(); + registerDecoderMetrics(registry, decoder); + + const body = registry.render(); + assert.match(body, /^xchain_decoder_poll_silent 0$/m); + assert.match(body, /^xchain_decoder_last_poll_timestamp_seconds \d/m); + }); + + it('shows a loop that died while caught up, which stalled cannot', function () { + // The headline gap. A caught-up decoder makes no chain progress, so isStalled() + // reads false BY DESIGN; only the iteration heartbeat separates "idle because + // there is nothing to do" from "the loop is gone". Both series in one case, + // because it is their disagreement that is the signal. + const registry = new Registry(); + const decoder = makeRunningDecoder(); + decoder.lastProcessedBlockIndex = 150; + decoder.blockchainInfoLastBlock = 150; + decoder.lastPollAt = Date.now() - (4 * 900000); + registerDecoderMetrics(registry, decoder); + + const body = registry.render(); + assert.match(body, /^xchain_decoder_poll_silent 1$/m); + assert.match(body, /^xchain_decoder_stalled 0$/m); + }); + + it('emits no last-poll timestamp before the first iteration, but still reports not-silent', function () { + // lastPollAt 0 means the loop has not run yet (long initial sync), which + // isPollSilent() reads as not silent; a 0 timestamp series would read as 1970. + const registry = new Registry(); + registerDecoderMetrics(registry, makeDecoder()); + const body = registry.render(); + assert.ok(!/xchain_decoder_last_poll_timestamp_seconds/.test(body)); + assert.match(body, /^xchain_decoder_poll_silent 0$/m); + }); + // Reorg churn had no decoder-side signal at all: the durable REORG rows are // DB-only and the indexer's reorgsProcessed needs the indexer to be up, so a // metrics-only deployment could watch a decoder thrash through shallow reorgs diff --git a/test/unit/rpcLookupFailure.test.js b/test/unit/rpcLookupFailure.test.js index ab750a4..1e87f2a 100644 --- a/test/unit/rpcLookupFailure.test.js +++ b/test/unit/rpcLookupFailure.test.js @@ -306,4 +306,149 @@ describe('XChainDecoder RPC-lookup + rollback-signal hardening', function () { assert.strictEqual(calls.commitTransaction, 1) }) }) + + // The other half of the classification. The prevout helpers must not wrap the RPC + // fetch AND the wire-decode of its response in one try that tags everything escaping + // it as rpcLookupFailure: a deterministic decode fault would then take the unbounded + // height retry above and wedge the decoder at that height forever, bypassing the + // quarantine ladder. getRawTransaction answers with a whole JSON-decoded hex string + // or fails, so a decode throw is CONTENT every instance sees alike: it must escape + // untagged. + describe('wire-decode faults escape untagged', function () { + const BAD_HEX = 'deadbeef' + + function decodeFaultDecoder(feeDestination = null) { + const decoder = new XChainDecoder( + 'bitcoin-regtest', 'h', '0', 'db', 'u', 'p', 'h', '0', 'u', 'p', false, feeDestination + ) + decoder.connector = { getRawTransaction: async () => BAD_HEX } + decoder.xchainBlockDecoder = { + transactionFromHex: () => { throw new Error('RangeError: value out of range') } + } + return decoder + } + + function untagged(err) { + assert.strictEqual(err.rpcLookupFailure, undefined, + 'a decode fault must not be tagged as a transport fault') + return true + } + + it('getSourceFromOutput: an undecodable prevout throws untagged', async function () { + const decoder = decodeFaultDecoder() + await assert.rejects(() => decoder.getSourceFromOutput('aa'.repeat(32), 0), untagged) + assert.strictEqual(decoder.rpcErrors, 0, 'a decode fault is not an RPC error') + }) + + it('getSourceFromOutput: an undecodable commit funder throws untagged', async function () { + // Reach the P2SH walk-back: the first decode answers a P2SH data-carrier + // output, the second (the commit's own funder) is the one that cannot parse. + const p2shScript = Buffer.alloc(23) + p2shScript[0] = 0xa9 + p2shScript[1] = 0x14 + p2shScript[22] = 0x87 + + const decoder = decodeFaultDecoder() + let decodes = 0 + decoder.xchainBlockDecoder = { + transactionFromHex: () => { + decodes++ + if (decodes === 1) { + return { + outs: [{ script: p2shScript }], + ins: [{ hash: Buffer.alloc(32, 2), index: 0 }] + } + } + throw new Error('RangeError: value out of range') + } + } + + await assert.rejects(() => decoder.getSourceFromOutput('aa'.repeat(32), 0), untagged) + assert.strictEqual(decodes, 2, 'the walk-back hop must have been reached') + assert.strictEqual(decoder.rpcErrors, 0) + }) + + it('getEnvelopeSourceFromCommit: an undecodable commit funder throws untagged', async function () { + const decoder = decodeFaultDecoder() + const commitTransaction = { ins: [{ hash: Buffer.alloc(32, 1), index: 0 }] } + await assert.rejects(() => decoder.getEnvelopeSourceFromCommit(commitTransaction), untagged) + assert.strictEqual(decoder.rpcErrors, 0) + }) + + it('fetchEnvelopeCommitTransaction: an undecodable commit throws untagged', async function () { + const decoder = decodeFaultDecoder() + await assert.rejects(() => decoder.fetchEnvelopeCommitTransaction('bb'.repeat(32)), untagged) + assert.strictEqual(decoder.rpcErrors, 0) + }) + + it('findFundingFeeOutputs: an undecodable funding tx throws untagged', async function () { + const decoder = decodeFaultDecoder('bcrt1qfeedest000000000000000000000000000000') + await assert.rejects(() => decoder.findFundingFeeOutputs('cc'.repeat(32)), untagged) + assert.strictEqual(decoder.rpcErrors, 0) + }) + + it('the block loop quarantines an undecodable prevout instead of retrying forever', async function () { + const { decoder, calls } = buildDecoder({ transactions: [fakeTx('cafe04')] }) + decoder.xchainBlockDecoder.transactionFromHex = () => { + throw new Error('RangeError: value out of range') + } + decoder.connector.getRawTransaction = async () => BAD_HEX + + // Bounded so the pre-fix behaviour (a tagged error, retried at this height + // for ever) fails the assertions instead of hanging the suite. + let attempts = 0 + decoder.parseTransaction = async () => { + attempts++ + if (attempts > 20){ + decoder.stopFlag = true + return null + } + return await decoder.getSourceFromOutput('aa'.repeat(32), 0) + } + + await decoder.start() + + assert.strictEqual(attempts, 4, 'TX_PARSE_MAX_RETRIES block retries, then quarantine') + assert.strictEqual(calls.insertEvent.length, 1, 'the poison tx must be quarantined once') + assert.strictEqual(calls.insertEvent[0].code, 'PARSE_ERROR') + }) + }) + + // Quarantine is parity-safe only for a fault every instance shares. An inactive + // BigInt-safe bufferutils reader makes a DOGE output > 2^53-1 sat undecodable on + // THIS instance alone, so after the change above it would quarantine a transaction + // healthy instances decode. Refusing to start is the only convergent answer. + describe('start() refuses a Dogecoin decoder with an inactive BigInt reader', function () { + const bufferutils = require('bitcoinjs-lib/src/bufferutils') + + function withInactiveReader(run) { + const originalReadUInt64 = bufferutils.BufferReader.prototype.readUInt64 + bufferutils.BufferReader.prototype.readUInt64 = function () { + throw new Error('RangeError: value out of range') + } + return (async () => { + try { + await run() + } finally { + bufferutils.BufferReader.prototype.readUInt64 = originalReadUInt64 + } + })() + } + + it('throws instead of warning and running on', async function () { + await withInactiveReader(async () => { + const { decoder } = buildDecoder() + decoder.xchainBlockDecoder.coin = 'dogecoin' + await assert.rejects(() => decoder.start(), /BigInt-safe 64-bit reader is NOT active/) + }) + }) + + it('leaves a non-Dogecoin decoder alone', async function () { + await withInactiveReader(async () => { + const { decoder, calls } = buildDecoder() + await decoder.start() + assert.strictEqual(calls.commitTransaction, 1, 'a BTC decoder still starts') + }) + }) + }) }) diff --git a/test/unit/sql-quote-backslash-escapes.test.js b/test/unit/sql-quote-backslash-escapes.test.js new file mode 100644 index 0000000..3ae4ba2 --- /dev/null +++ b/test/unit/sql-quote-backslash-escapes.test.js @@ -0,0 +1,133 @@ +'use strict'; + +/********************************************************************* + * + * Copyright © 2025–2026 Dankest, LLC + * Based on XChain Platform by Dankest, LLC – https://dankest.llc + * + * SPDX-License-Identifier: AGPL-3.0-or-later + * + * This file is part of XChain Platform. Licensed under the GNU Affero + * General Public License v3.0 or later; see LICENSE.md. A commercial + * license (without AGPL source-disclosure terms) is available - + * contact legal@dankest.llc. + * + ********************************************************************** + * SQL quote walkers model MariaDB/MySQL backslash escapes. + * + * MariaDB/MySQL honour `\` inside `'` and `"` string literals whenever + * sql_mode omits NO_BACKSLASH_ESCAPES, which nothing in this tree sets. The four + * walkers used to treat a doubled quote as the ONLY escape, so a `\'` closed the + * span early, the literal's real closing quote re-opened it, and the following + * `;` plus everything up to the next quote merged into one chunk. A `DROP TABLE` + * then rode inside a chunk whose first keyword was INSERT, where the ^-anchored + * keyword checks in _destructiveAutoStatement never saw it and the file scored + * auto-eligible. + * + * These assertions fail against the pre-fix walkers: reverting the + * opensBackslashEscape branch in src/db.js turns the split counts back to 1 and + * the destructive offender back to null. + * + ********************************************************************/ + +const assert = require('assert'); + +const Database = require('../../src/db'); + +// Same binding technique migration-runner.test.js uses: the walkers are pure, so +// bind them to the prototype rather than standing up a live Database. +const stripComments = Database.prototype.stripSqlLineComments.bind({}); +const destructiveOf = Database.prototype._destructiveAutoStatement.bind(Database.prototype); +const statementsOf = (raw) => Database.prototype.splitSqlStatements.call(Database.prototype, raw); +const isIdRepair = Database.prototype._isIdRepairUpdate.bind(Database.prototype); + +// Build the literal backslash out of a charCode so no layer of source escaping can +// quietly turn `\'` into `\\'` and make the test assert a different string than the +// one the failure needs. +const BS = String.fromCharCode(92); + +describe('SQL quote walkers honour backslash escapes @regression', function () { + + it('splits INSERT-with-\\\' then DROP into two statements, not one', function () { + const raw = "INSERT INTO index_memos (memo) VALUES ('it" + BS + "'s fine');\n" + + 'DROP TABLE balances;\n'; + const stmts = statementsOf(raw); + assert.strictEqual(stmts.length, 2, + 'the server runs two statements here; a desynced walker returns one merged chunk'); + assert.ok(/^INSERT\b/i.test(stmts[0]), 'first statement is the INSERT'); + assert.ok(/^DROP\s+TABLE\b/i.test(stmts[1]), 'second statement is the DROP'); + }); + + it('flags the DROP hidden behind a backslash-escaped quote as destructive DDL', function () { + const raw = "INSERT INTO index_memos (memo) VALUES ('it" + BS + "'s fine');\n" + + 'DROP TABLE balances;\n'; + const offender = destructiveOf(statementsOf(raw)); + assert.ok(offender, 'a mode=auto file carrying this DROP must not score auto-eligible'); + assert.ok(/^DROP\s+TABLE\b/i.test(offender), 'the offender is the DROP, got: ' + offender); + }); + + it('applies the same rule inside a double-quoted literal', function () { + const raw = 'INSERT INTO index_memos (memo) VALUES ("it' + BS + '"s fine");\n' + + 'DROP TABLE balances;\n'; + const stmts = statementsOf(raw); + assert.strictEqual(stmts.length, 2); + assert.ok(/^DROP\s+TABLE\b/i.test(destructiveOf(stmts) || '')); + }); + + it('does NOT treat a backslash inside a backtick identifier as an escape', function () { + // Backslash is a literal character inside an identifier quote, so the + // backtick closes the span and the `;` terminates the statement. + const raw = 'ALTER TABLE `t' + BS + '` ADD COLUMN a INT;\nDROP TABLE balances;\n'; + const stmts = statementsOf(raw); + assert.strictEqual(stmts.length, 2, + 'consuming `\\`` would swallow the terminator and desync the other way'); + assert.ok(/^DROP\s+TABLE\b/i.test(stmts[1])); + }); + + it('still treats a doubled quote as an escape', function () { + const raw = "INSERT INTO t (a) VALUES ('it''s fine');\nDROP TABLE balances;\n"; + const stmts = statementsOf(raw); + assert.strictEqual(stmts.length, 2); + assert.ok(/^DROP\s+TABLE\b/i.test(stmts[1])); + }); + + it('preserves a -- sequence inside a backslash-escaped literal instead of stripping it', function () { + const raw = "INSERT INTO t (a) VALUES ('x" + BS + "' -- y');\nSELECT 1;\n"; + const out = stripComments(raw); + assert.ok(out.includes('-- y'), + 'the `-- y` sits inside the literal; stripping it corrupts the statement'); + assert.ok(out.includes('SELECT 1')); + }); + + it('preserves a # inside a backslash-escaped literal', function () { + const raw = "INSERT INTO t (a) VALUES ('x" + BS + "' # y');\nSELECT 1;\n"; + assert.ok(stripComments(raw).includes('# y')); + }); + + it('does not let a backslash-escaped quote hide a # from hasUnquotedHash', function () { + // The `#` here is OUTSIDE the literal once the escape is modelled, so the + // classifier must refuse the statement rather than read past a comment. + const raw = "UPDATE cfg SET v = '" + BS + "'# hidden\n' WHERE id = 0;\n"; + assert.ok(destructiveOf(statementsOf(raw)), 'a visible # makes the statement non-auto-eligible'); + }); + + it('does not throw or hang on input ending in a lone backslash inside an open literal', function () { + const raw = "INSERT INTO t (a) VALUES ('x" + BS; + assert.doesNotThrow(() => statementsOf(raw)); + assert.doesNotThrow(() => stripComments(raw)); + assert.doesNotThrow(() => destructiveOf([raw])); + }); + + it('_isIdRepairUpdate keeps recognising the committed repair shape', function () { + const repair = 'UPDATE `mirror` SET id = (SELECT COALESCE(MAX(t.id), 0) + 1 FROM (SELECT id FROM `mirror`) t) WHERE id = 0'; + assert.strictEqual(isIdRepair(repair), true); + }); + + it('_isIdRepairUpdate is not fooled by a backslash-escaped quote in the subquery', function () { + // A `\'` inside the subquery must not close the span early: the paren scan + // unbalances and rejects a legitimate repair (or accepts a bogus one). + const repair = 'UPDATE `mirror` SET id = (SELECT COALESCE(MAX(id), 0) + 1 FROM `mirror` WHERE tag = ' + + "'it" + BS + "'s') WHERE id = 0"; + assert.strictEqual(isIdRepair(repair), true); + }); +}); From 0756fd5b4b03cb9ed078b0fb4b2a4764a2d3a6dc Mon Sep 17 00:00:00 2001 From: J-Dog Date: Sat, 29 Aug 2026 15:03:23 -0700 Subject: [PATCH 2/7] docs: correct the version badge to the released version --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 43ae2a8..2998a1c 100644 --- a/README.md +++ b/README.md @@ -4,7 +4,7 @@ # XChain Platform Decoder

- Version + Version Tests Node License From 8ba2f278e507c73fd98e9907b567d49e2e1a51ff Mon Sep 17 00:00:00 2001 From: J-Dog Date: Sun, 30 Aug 2026 10:54:13 -0700 Subject: [PATCH 3/7] observability: route this service's console through the shared log shim The service logged free text through bare console calls, so its lines carried no level, no timestamp and no service tag, and LOG_LEVEL and LOG_FORMAT changed nothing an operator could see on any box. patchConsole() goes at the very top of the entry file, above the env-validation gates. Those gates run hundreds of lines before the existing wiring point, and their failures are among the lines an operator most needs framed. The shim's vendored copy is re-synced from the canonical module in xchain-hub in the same change, which brings the credential scrub that catches prefixed names like SERVICE_DB_SECRET= and the token after Bearer. The test bootstrap sets XCHAIN_LOG_PATCH=0 so the suites keep seeing stock console regardless of require order. Where this repo carries its own ported copy of the observability or metrics suite, it is re-ported from the canonical one rather than hand-edited, per the note those files carry. Two contract changes travel with it: the metrics registry is always constructed and only the endpoint stays gated, so a counter registered by a module exists on the default fleet instead of nowhere; and an identical metric re-declaration returns the registered metric rather than throwing, while a different shape still throws. READMEs gain the shim-control env table. --- README.md | 16 +++ src/api.js | 11 ++ src/observability/README.md | 53 ++++++++- src/observability/index.js | 202 +++++++++++++++++++++++++++++--- src/observability/logShipper.js | 82 +++++++++++-- src/observability/metrics.js | 20 +++- test/unit/setup.js | 8 ++ 7 files changed, 365 insertions(+), 27 deletions(-) diff --git a/README.md b/README.md index 2998a1c..3445870 100644 --- a/README.md +++ b/README.md @@ -90,6 +90,22 @@ The module is vendored byte-identically from xchain-hub. Edit it there and re-run `xchain-hub/bin/sync-observability.sh`; a local edit fails the parity check CI runs across the vendored copies. +### Shim controls, and the defaults in force + +These four names configure the shim itself. The fleet deploy path carries them +into the container: `xchain-node` forwards any of them set in the module config +store or in the deploy host's environment (`ModuleService.resolveObservabilityEnv`), +and the validator compose files under `claude/deploy/testnet-validators/` name +them outright. Nothing is fabricated when neither source sets one, so these +defaults hold on an unconfigured box: + +| Variable | Default | Effect | +|---|---|---| +| `LOG_LEVEL` | `info` | Lowest level emitted. `debug` \| `info` \| `warn` \| `error`; an unrecognised value falls back to `info`. | +| `LOG_FORMAT` | `text` | `text` emits ` [] key=value`; `json` emits one NDJSON record per line. | +| `METRICS_ENABLED` | `false` | Registers the `/metrics` route. The counter registry is built either way, so counters are collected whether or not the route is exposed. | +| `XCHAIN_LOG_PATCH` | `1` | Routes bare `console.*` calls through the shim so they carry the level and service prefix. `0` leaves `console` untouched, which is what the test bootstrap sets. | + ## Scripts | Command | Description | diff --git a/src/api.js b/src/api.js index 845082a..cb23598 100644 --- a/src/api.js +++ b/src/api.js @@ -21,6 +21,17 @@ const dotenv = require('dotenv') dotenv.config() +// Before anything else logs. The env-validation failure at startApi()'s +// DECODER_API_PORT check is exactly the line an operator needs levelled and +// timestamped, and installObservability does not run until ~200 lines further +// down. +const { patchConsole } = require('./observability'); +patchConsole({ + service: 'xchain-decoder', + version: require('../package.json').version, + coin: process.env.COIN || '', + network: process.env.NETWORK || '' +}); const express = require('express'); const bodyParser = require('body-parser'); diff --git a/src/observability/README.md b/src/observability/README.md index e411c8b..b40fd9d 100644 --- a/src/observability/README.md +++ b/src/observability/README.md @@ -10,6 +10,22 @@ across the vendored copies fails on drift; run it locally with ## Wiring a service +Two calls, and the first one goes at the very TOP of the entry file, above the +env-validation gates: + +```js +const { patchConsole } = require('./observability'); +patchConsole({ service: 'xchain-hub', version: require('../package.json').version }); +``` + +That routes the service's existing bare `console.*` calls through the shim, so +`LOG_LEVEL`, `LOG_FORMAT` and secret redaction apply to every call site without +rewriting one of them. It has to run before anything logs: every service emits +its env-validation and crash lines hundreds of lines ahead of +`installObservability`, and those are the lines an operator most needs framed. + +Then, where the Express app exists: + ```js const { installObservability } = require('./observability'); @@ -25,11 +41,41 @@ Call it right after `helmet`/`cors`/`express.json` and before the routes, so the request timer wraps every handler. It returns `{ enabled, config, registry, logger, shutdown }`. +Modules that need to emit an event with FIELDS (a patched `console` line cannot +carry any) take `getLogger()`, which resolves lazily and is safe to call at +require time: + +```js +const { getLogger } = require('./observability'); +const log = getLogger(); +log.warn('PBFT_DROP', { reason: 'digest_mismatch', phase: 'prepare', round }); +``` + +## The default text line + +The fleet runs text mode, so text mode carries the whole record: + +``` +2026-08-30T17:11:25.030Z warn [xchain-hub] PBFT_DROP reason=digest_mismatch phase=prepare round=42 +``` + +The message sits immediately after the service tag so every existing substring +grep across the platform keeps matching: the prefix is the only addition. The +level token is lowercase deliberately: the server-monitor agent +counts `grep -cE 'ERROR|FATAL'` per container and pages at 50/min, so an +uppercase token would make every `console.error` line count and page the fleet +on first deploy. + ## Everything is off by default -With no env set: no route is registered, no timer starts, no socket opens, and -`logger` is a console passthrough that prints the same plain text as before. -Turning it on is an operator decision. +With no env set: no route is registered, no timer starts and no socket opens. +Turning any of that on is an operator decision. + +The metrics REGISTRY is the one exception, and it is always constructed. Gating +it on `METRICS_ENABLED` meant a counter registered by a consensus module did not +exist at all on the default fleet, which is every box: nothing could record into +it, so enabling metrics later started from zero history rather than revealing +what had happened. Only the endpoint is gated. | Env | Default | Effect | | --- | --- | --- | @@ -39,6 +85,7 @@ Turning it on is an operator decision. | `METRICS_HTTP` | on when metrics on | Per-request counters and latency histogram | | `LOG_FORMAT` | `text` | `json` emits NDJSON records | | `LOG_LEVEL` | `info` | `debug`/`info`/`warn`/`error` | +| `XCHAIN_LOG_PATCH` | on | `0` leaves `console.*` alone; every repo's test bootstrap sets it | | `LOG_SHIP_ENABLED` | off | Ship batches; needs `LOG_SHIP_URL` too | | `LOG_SHIP_URL` | unset | Collector endpoint (http/https), NDJSON body | | `LOG_SHIP_TOKEN` | unset | Bearer token for the collector; never logged | diff --git a/src/observability/index.js b/src/observability/index.js index 8268aeb..f07981c 100644 --- a/src/observability/index.js +++ b/src/observability/index.js @@ -14,13 +14,22 @@ * * XChain shared observability - service wiring * - * One call, installObservability(app, { service }), gives an xchain-* service a - * Prometheus /metrics endpoint plus a structured log shim. Both are DEFAULT - * OFF: with no env set the call registers no route, starts no timer, opens no - * socket, and returns a handle whose logger is a thin console passthrough. That - * is deliberate. These services are consensus-critical and public-facing, so a - * new listening surface has to be an operator decision, not a side effect of a - * deploy. + * Two calls wire an xchain-* service up: + * + * patchConsole({ service }) at the TOP of the entry file, before any + * line is logged; routes bare console.* calls + * through the shim so levels, formats and + * redaction apply without rewriting call + * sites. + * installObservability(app, ...) where the Express app exists; adds the + * /metrics route and HTTP instrumentation. + * + * No socket and no route without env: METRICS_ENABLED alone opens the endpoint, + * and shipping needs both LOG_SHIP_ENABLED and a URL. These services are + * consensus-critical and public-facing, so a new listening surface stays an + * operator decision rather than a side effect of a deploy. The metrics REGISTRY + * is not gated, only the endpoint is: counters have to exist on the default + * fleet or nothing can ever record into them. * * Env (all optional): * METRICS_ENABLED=1 turn the endpoint on (default off) @@ -30,6 +39,7 @@ * when metrics are enabled; set 0 for endpoint-only) * LOG_FORMAT=json emit NDJSON log lines instead of plain text * LOG_LEVEL=info debug|info|warn|error + * XCHAIN_LOG_PATCH=0 leave console.* alone (test bootstraps set this) * LOG_SHIP_ENABLED=1 + LOG_SHIP_URL=... POST NDJSON batches to a collector * (see logShipper.js for the remaining LOG_SHIP_* tuning knobs) * @@ -45,9 +55,31 @@ 'use strict'; const crypto = require('crypto'); +const util = require('util'); const { Registry, collectDefaultMetrics, DEFAULT_DURATION_BUCKETS } = require('./metrics'); const { createLogShipper, readLogEnv } = require('./logShipper'); +// Process-wide handles. A service is one process loading exactly one vendored +// copy of this module, so module scope is the right scope: a globalThis key +// would buy nothing and would collide across a monorepo test run. +let _logger = null; +let _registry = null; +let _patched = null; +// The shipper's housekeeping counters (log_lines_emitted_total and friends) +// can only be registered once per registry. Now that the registry is shared and +// always constructed, a second shipper on it would throw at construction, which +// on the real wiring path (patchConsole at the top of api.js, then +// installObservability further down) would take the service out at startup. +let _shipperAttached = false; +// The bound pre-patch console. Every shipper built after patchConsole must +// write HERE, not to the global console: the shim's default sink is the global +// object by reference, so a second shipper taking that default would emit its +// formatted line INTO the patched console and get it formatted a second time +// (` warn [svc] warn [svc] msg`). +let _sink = null; + +const CONSOLE_METHODS = { log: 'info', info: 'info', warn: 'warn', error: 'error', debug: 'debug' }; + function toBool(v, fallback = false) { if (v === undefined || v === null || v === '') return fallback; return /^(1|true|yes|on)$/i.test(String(v)); @@ -130,18 +162,27 @@ function installObservability(app, opts = {}) { coin = '', network = '', env = process.env, - console: sink = console + console: sink = null } = opts; const config = readObservabilityEnv(env); - let registry = null; - if (config.metricsEnabled) { - registry = new Registry(); - collectDefaultMetrics(registry, { service, version, coin, network }); - } + // The registry is ALWAYS constructed, and only the /metrics route is gated. + // Building it under METRICS_ENABLED meant every counter a consensus module + // registers "when metrics are on" simply did not exist on the default + // fleet, which is every box: the counters were unreachable, not merely + // unscraped. Registering series costs nothing until something renders them. + const registry = getRegistry({ service, version, coin, network }); - const logger = createLogShipper({ service, version, env, console: sink, registry, transport: opts.logTransport || null }); + // One process, one shipper. When patchConsole already built it and this + // caller wants no special sink or transport, adopt it rather than running a + // second one: two shippers would split the line counters and each hold + // their own ship buffer. + const adopt = _logger && !opts.console && !opts.logTransport; + const logger = adopt + ? _logger + : newShipper({ service, version, env, console: sink, transport: opts.logTransport || null }); + if (!_logger) _logger = logger; if (!config.metricsEnabled || !app || typeof app.use !== 'function') { return { @@ -229,11 +270,142 @@ function installObservability(app, opts = {}) { }; } +/** + * The process's metrics registry, created on first ask. Consensus modules + * register counters at require time, long before installObservability runs, + * so this must not depend on the wiring order of any api.js. + */ +function getRegistry(info = {}) { + if (!_registry) { + _registry = new Registry(); + collectDefaultMetrics(_registry, { + service: info.service || 'xchain-service', + version: info.version || '', + coin: info.coin || '', + network: info.network || '' + }); + } + return _registry; +} + +// Returned once and resolved on every call, so a module can do +// `const log = getLogger()` at require time and still reach the real shipper +// once patchConsole/installObservability has run. Before either, it falls +// through to the global console rather than throwing: a module that logs while +// being required must not be able to kill the process. +const _lazyLogger = { + log(level, msg, fields) { + if (_logger) return _logger.log(level, msg, fields); + const fn = level === 'error' ? console.error : level === 'warn' ? console.warn : console.log; + fn(fields && Object.keys(fields).length ? `${msg} ${util.inspect(fields, { depth: 2 })}` : String(msg)); + return null; + }, + debug(msg, fields) { return this.log('debug', msg, fields); }, + info(msg, fields) { return this.log('info', msg, fields); }, + warn(msg, fields) { return this.log('warn', msg, fields); }, + error(msg, fields) { return this.log('error', msg, fields); } +}; + +function getLogger() { return _lazyLogger; } + +// Attaches the shared registry to the FIRST shipper only; later shippers get +// their own line accounting and leave the shared series alone. +function newShipper(opts) { + const registry = _shipperAttached ? null : getRegistry(opts); + if (registry) _shipperAttached = true; + return createLogShipper({ ...opts, console: opts.console || _sink || console, registry }); +} + +/** + * Routes the service's existing bare console.* calls through the log shim, so + * levels, formats and redaction apply to the ~850 hub call sites and their + * siblings without rewriting one of them. + * + * Called at the TOP of an entry file, before anything logs. Every service logs + * before installObservability runs today (hub api.js:29 vs :407, and the same + * shape in the decoder, indexer, encoder and tracker), and the lines that get + * lost that way are the env-validation and crash lines an operator most needs + * framed. That is why this is a separate call rather than part of install. + * + * Set XCHAIN_LOG_PATCH=0 to disable, which is what each repo's test bootstrap + * does: the suites stub and reassign console freely, and they must see stock + * console regardless of require order. + * + * @param {object} opts + * @param {string} opts.service service name stamped on every line + * @returns {{patched:boolean, logger:object, unpatch:function}} + */ +function patchConsole(opts = {}) { + const { service = 'xchain-service', version = '', coin = '', network = '', env = process.env } = opts; + + if (_patched) return _patched; + if (String(env.XCHAIN_LOG_PATCH || '') === '0') { + return { patched: false, logger: getLogger(), unpatch: () => {} }; + } + + // Bind the originals into a NEW object BEFORE replacing anything. The shim's + // default sink is the global console object by reference, so handing the + // logger the live console and then patching it makes every line recurse + // into itself. + const sink = {}; + const originals = {}; + for (const name of Object.keys(CONSOLE_METHODS)) { + const fn = typeof console[name] === 'function' ? console[name] : console.log; + originals[name] = console[name]; + sink[name] = fn.bind(console); + } + sink.log = sink.log || sink.info; + _sink = sink; + + const logger = newShipper({ service, version, coin, network, env, console: sink }); + _logger = logger; + + for (const [name, level] of Object.entries(CONSOLE_METHODS)) { + // util.format is console's own argument semantics: printf-style format + // strings resolve (about 40 hub sites use them) and a trailing Error + // keeps its stack. A trailing object is NOT promoted into fields; + // structured fields come from getLogger(), never from a guess about + // what a console call meant. + console[name] = (...args) => { logger.log(level, util.format(...args)); }; + } + + _patched = { + patched: true, + logger, + unpatch() { + for (const [name, fn] of Object.entries(originals)) { + if (fn === undefined) delete console[name]; + else console[name] = fn; + } + _patched = null; + _sink = null; + if (_logger === logger) _logger = null; + } + }; + return _patched; +} + +function unpatchConsole() { if (_patched) _patched.unpatch(); } + +// Tests only: drops the process-wide handles so an assertion about a fresh +// process does not inherit the previous test's shipper or registry. +function _resetObservability() { + unpatchConsole(); + _logger = null; + _registry = null; + _shipperAttached = false; +} + module.exports = { installObservability, readObservabilityEnv, routeLabel, Registry, collectDefaultMetrics, - createLogShipper + createLogShipper, + patchConsole, + unpatchConsole, + getLogger, + getRegistry, + _resetObservability }; diff --git a/src/observability/logShipper.js b/src/observability/logShipper.js index c76de8c..d232afa 100644 --- a/src/observability/logShipper.js +++ b/src/observability/logShipper.js @@ -47,13 +47,74 @@ const LEVELS = { debug: 10, info: 20, warn: 30, error: 40 }; // Key names whose values never leave the box in a log line. const SECRET_KEY_RE = /(pass(word|phrase)?|secret|token|api[_-]?key|apikey|auth|credential|wif|priv(ate)?[_-]?key|mnemonic|seed|cookie|session)/i; -// `password=hunter2`, `api_key: abc`, `token="x"` embedded in free text. -const SECRET_INLINE_RE = /\b(pass(?:word|phrase)?|secret|token|api[_-]?key|apikey|authorization|credential|wif|priv(?:ate)?[_-]?key|mnemonic|seed)\b(\s*[:=]\s*)("[^"]*"|'[^']*'|\S+)/gi; +// `password=hunter2`, `api_key: abc`, `token="x"`, `HUB_DB_SECRET=...` embedded +// in free text. +// +// The key is allowed to carry a prefix and a suffix, and the leading boundary is +// "not preceded by another key character" rather than `\b`. `\b` does not fire +// between two word characters, and `_` is a word character, so an anchored +// pattern silently misses every env-shaped name the services actually print: +// `HUB_DB_SECRET`, `INDEXER_DB_PASS`, `db_password`. Those are precisely what an +// env-validation failure puts on stdout, and with LOG_SHIP_* on they would go +// off-box in the clear. +const SECRET_INLINE_RE = /(? `${key}${sep}${REDACTED}`); + return String(msg) + .replace(SECRET_INLINE_RE, (_m, keyAndSep) => `${keyAndSep}${REDACTED}`) + .replace(BEARER_RE, REDACTED); +} + +// Envelope keys are rendered as the line's own prefix, so they never repeat in +// the key=value tail. +const ENVELOPE_KEYS = new Set(['ts', 'level', 'service', 'msg', 'version']); + +// A bare token only where it cannot be confused with the next pair: anything +// carrying whitespace, `=` or a quote is JSON-quoted so a reader can split the +// tail on unquoted spaces. This is the half of the text format the watch +// collector's parser is written against (claude/scripts/xchain-watch.js). +function formatFieldValue(value) { + if (value === null) return 'null'; + if (typeof value === 'string') { + return value !== '' && !/[\s"'=]/.test(value) ? value : JSON.stringify(value); + } + if (typeof value === 'number' || typeof value === 'boolean') return String(value); + let json; + try { json = JSON.stringify(value); } catch { json = '"[unserializable]"'; } + if (json === undefined) json = 'null'; + return /[\s]/.test(json) ? JSON.stringify(json) : json; +} + +/** + * Renders a record as the fleet's default text line: + * + * [] key=value key=value + * + * The message stays immediately after the service tag so every existing + * substring grep across the platform (handover greps, StatusService, the + * decoder's wait loops) keeps matching: the prefix is the only addition. The level token is lowercase on purpose: an uppercase ERROR would + * be counted by the server-monitor's `grep -cE 'ERROR|FATAL'` rate alert on + * every console.error line and page the fleet on first deploy. + */ +function formatTextLine(record) { + let line = `${record.ts} ${record.level} [${record.service}] ${record.msg}`; + for (const [k, v] of Object.entries(record)) { + if (ENVELOPE_KEYS.has(k) || v === undefined) continue; + line += ` ${String(k).replace(/[\s"'=]/g, '_')}=${formatFieldValue(v)}`; + } + return line; } // Depth-limited so a cyclic or huge object cannot stall the hot path; anything @@ -181,7 +242,7 @@ class LogShipper { this.stats.emitted += 1; if (this._levelCounter) this._levelCounter.inc({ level }, 1); - this._emitLocal(level, record, msg); + this._emitLocal(level, record); if (this.config.shipEnabled) this._enqueue(record); return record; } @@ -191,13 +252,16 @@ class LogShipper { warn(msg, fields) { return this.log('warn', msg, fields); } error(msg, fields) { return this.log('error', msg, fields); } - _emitLocal(level, record, rawMsg) { + _emitLocal(level, record) { const fn = level === 'error' ? (this.console.error || this.console.log) : level === 'warn' ? (this.console.warn || this.console.log) : this.console.log; if (!fn) return; + // Both modes carry the same record. Printing only the scrubbed message + // here would discard every field, and the fleet runs text mode, so the + // fields would exist nowhere an operator can reach. if (this.config.format === 'json') fn.call(this.console, JSON.stringify(record)); - else fn.call(this.console, scrubMessage(rawMsg)); + else fn.call(this.console, formatTextLine(record)); } _enqueue(record) { @@ -269,4 +333,8 @@ class LogShipper { function createLogShipper(opts = {}) { return new LogShipper(opts); } -module.exports = { LogShipper, createLogShipper, readLogEnv, redactFields, scrubMessage, LEVELS, REDACTED }; +module.exports = { + LogShipper, createLogShipper, readLogEnv, redactFields, scrubMessage, + formatTextLine, formatFieldValue, LEVELS, REDACTED, + SECRET_KEY_RE, SECRET_INLINE_RE +}; diff --git a/src/observability/metrics.js b/src/observability/metrics.js index 2a99d40..656191a 100644 --- a/src/observability/metrics.js +++ b/src/observability/metrics.js @@ -279,9 +279,25 @@ class Registry { this.seriesDropped.inc({ metric: metricName }, 1); } + // Re-declaring the SAME metric hands back the one already registered; + // re-declaring a name with a different type or label set still throws, + // because that is a genuine collision that would corrupt the exposition. + // + // The distinction earns its keep now that the registry is process-wide and + // always constructed: modules register their counters wherever they happen + // to be required, and a service that wires observability twice must not die + // at startup over a duplicate declaration that asks for exactly what is + // already there. _register(metric) { - if (this.metrics.has(metric.name)) { - throw new Error(`metric already registered: ${metric.name}`); + const existing = this.metrics.get(metric.name); + if (existing) { + const same = existing.type === metric.type + && existing.labelNames.length === metric.labelNames.length + && existing.labelNames.every((n, i) => n === metric.labelNames[i]); + if (!same) { + throw new Error(`metric already registered with a different shape: ${metric.name}`); + } + return existing; } this.metrics.set(metric.name, metric); return metric; diff --git a/test/unit/setup.js b/test/unit/setup.js index 2126ff2..732b419 100644 --- a/test/unit/setup.js +++ b/test/unit/setup.js @@ -15,6 +15,14 @@ // reject 10x with ECONNABORTED do not spend real seconds sleeping. process.env.RPC_TIMEOUT_RETRY_DELAY_MS = '0' +// The suites stub, spy on and outright reassign the global console in dozens of +// files, and any test file that pulls in src/api.js would otherwise install the +// console patch for the whole run: from that point every assertion about a log +// line would be reading a formatted, level-gated line instead of what the code +// under test actually passed. The patch is a production wiring concern and is +// covered directly in the observability shim's own unit tests, which opt back in. +process.env.XCHAIN_LOG_PATCH = '0' + const Module = require('module') const originalResolveFilename = Module._resolveFilename From 8db0e4a7a775fc8ec18201281288d0b73c0cb490 Mon Sep 17 00:00:00 2001 From: J-Dog Date: Sun, 30 Aug 2026 14:16:39 -0700 Subject: [PATCH 4/7] decoder: a halt it cannot record is the one an operator never sees The halt path returns without writing a marker when the database layer has no markReorgHalted, and returned without saying anything either. The write FAILURE one line below was already logged; this branch is the genuinely silent one, and it is the worst case in the set: a decoder decides to stop, cannot persist why, and /status, /live and the JSON-RPC health method all go on reporting no halt. It now emits a REORG_HALT record carrying the reason and depth it was about to record, and says plainly that the marker could not be persisted so the health surfaces will not report it. The crash record carries the halt state, so a crash during a halt is distinguishable from an ordinary one, and an uncaughtException handler joins the rejection handler that was already there. The rejection handler still logs and continues; that choice is deliberate and unchanged. Both are registered inside startApi, because several suites require this module in-process under mocha and a module-scope exit would abort the run instead of failing one test. Six health-route catches swallowed their cause, five of them empty. If the halt probe threw, the routes reported no halt: a halted decoder that reads healthy. They now log at warn, throttled per probe and route, with the suppressed count on the next line. Without the throttle a database outage turns the rate limiter's ceiling into more log volume per hour than this service normally emits in a day, which would eat the retention window the caps are sized on. Control flow and status codes are untouched. In db.js, one catch of ten now logs: the temporary-table drop, which is the only one whose failure lands on a different, later query, so the next mempool diff fails on a table it did not create with nothing naming the drop that lost. The nine connection releases stay silent on purpose, reasoned at the site. The prose crash lines are gone. Each duplicated the record beside it, and a collector reading warn and above would file one crash as two findings. Nothing in the tree greps either string. --- src/XChainDecoder.js | 32 ++- src/api.js | 126 +++++++++- src/db.js | 24 +- test/unit/decoderHaltDiagnostics.test.js | 290 +++++++++++++++++++++++ 4 files changed, 460 insertions(+), 12 deletions(-) create mode 100644 test/unit/decoderHaltDiagnostics.test.js diff --git a/src/XChainDecoder.js b/src/XChainDecoder.js index 9b1b51a..d07dd4f 100644 --- a/src/XChainDecoder.js +++ b/src/XChainDecoder.js @@ -32,6 +32,11 @@ const { isOracleFeeCaptureActive, isOracleFeeSetCaptureActive, oracleAddressFrom const { isDispenserExpiryRealignActive } = require('./dispenserExpiryRealign') const { captureCommands, collapseDispenserRegistrations, isBatchSubCommandCaptureActive } = require('./batchSubCommandCapture') const { chainTierMismatch, chainFieldMissing, chainGenesisMismatch, chainGenesisUnpinned } = require('./chainIdentity') +// REORG_HALT rides getLogger() rather than this.logError, because a patched +// console line carries no structured fields and coin/network/reason/depth are +// the whole content of the event. getLogger() resolves lazily, so requiring it +// here is safe before patchConsole()/installObservability() has run. +const { getLogger } = require('./observability') const strictTextDecoder = new TextDecoder('utf-8', { fatal: true }) const lenientTextDecoder = new TextDecoder('utf-8') @@ -1756,7 +1761,32 @@ class XChainDecoder { this.reorgHaltReason = reason this.reorgHaltAt = new Date().toISOString() this.reorgHaltCheckedAt = Date.now() - if (typeof this.db.markReorgHalted !== 'function') return + + // A decoder that decides to halt and cannot record it anywhere is the + // worst shape this surface has: the process stops, every health route + // reads the durable marker that was never written, and the operator gets + // a stopped decoder with no reason on any surface they poll. The event + // goes out BEFORE the write is attempted, so the reason survives even + // when nothing durable can. + const canPersist = typeof this.db.markReorgHalted === 'function' + try { + getLogger().error('REORG_HALT', { + coin: this.coinTick, + network: this.consensusNetwork, + reason: reason, + depth: blocksDeleted.length, + marker_persisted: canPersist, + // Spelled out rather than left for the reader to infer from the + // boolean: this is the one halt that /status and /live cannot + // report, because the marker they read is never written. + detail: canPersist ? undefined + : 'db.markReorgHalted is unavailable: the durable halt marker cannot be persisted, ' + + 'so GET /status, GET /live and the JSON-RPC health method will NOT report this halt. ' + + 'This log line is the only record of it.' + }) + } catch (_) { /* a diagnostic must never mask the abort it describes */ } + + if (!canPersist) return try { await this.db.markReorgHalted(reason) } catch (e) { diff --git a/src/api.js b/src/api.js index cb23598..b4179f6 100644 --- a/src/api.js +++ b/src/api.js @@ -41,9 +41,61 @@ const rateLimit = require('express-rate-limit'); const XChainDecoder = require('./XChainDecoder'); const { resolveFeeDestination } = require('./feeDestination'); const jsonRouter = require('express-json-rpc-router') -const { installObservability } = require('./observability'); // default-off /metrics + structured log shim +const { installObservability, getLogger } = require('./observability'); // default-off /metrics + structured log shim const { registerDecoderMetrics } = require('./decoderMetrics'); // decoder feed-freshness gauges +// Records a health probe that threw, so the route's answer is not the only thing +// an operator has. The failure this closes is specific: when checkReorgHalt() +// throws, /live and /status answer reorg_halted false, so a decoder carrying a +// durable halt marker reads as clean on every surface an operator or the +// container healthcheck polls. db.ping() is the same shape: the probe fails, the +// route still answers, and nothing names which probe it was. +// +// Throttled per probe because these routes are caller-driven: the express rate +// limiter admits 100 requests per minute per IP, and a DB outage would otherwise +// turn each of them into a log line, spending the retention window this service's +// log caps are sized for on one repeated fault. The count of what was suppressed +// rides the next line out, so a throttled flood stays measurable. +const PROBE_LOG_WINDOW_MS = 60000; +const _probeLogState = new Map(); // probe key -> { suppressed, lastLoggedAt } + +function noteProbeFailure(probe, route, err) { + try { + const key = probe + '|' + route; + const now = Date.now(); + const seen = _probeLogState.get(key); + if (seen && (now - seen.lastLoggedAt) < PROBE_LOG_WINDOW_MS) { + seen.suppressed += 1; + return null; + } + const suppressed = seen ? seen.suppressed : 0; + _probeLogState.set(key, { suppressed: 0, lastLoggedAt: now }); + const fields = { + probe, + route, + err: err && err.message ? err.message : String(err) + }; + if (suppressed > 0) fields.suppressed = suppressed; + return getLogger().warn('HEALTH_PROBE_FAILED', fields); + } catch (_) { + // A health route must answer even when the thing describing it is broken. + return null; + } +} + +// Tests only: the throttle table is module-wide, so a case asserting a first line +// must not inherit the previous case's window. +function _resetProbeLogState() { _probeLogState.clear(); } + +// Tests only: rewinds every window past its edge while KEEPING the suppressed +// counts, so a case can assert what the next line reports about the flood it +// swallowed. Clearing the table instead would drop exactly the number under test. +function _ageProbeLogState() { + for (const entry of _probeLogState.values()) { + entry.lastLoggedAt -= (PROBE_LOG_WINDOW_MS + 1); + } +} + const NETWORK = process.env.NETWORK const NODE_URL = process.env.NODE_URL @@ -103,7 +155,7 @@ function registerLiveRoute(app, decoder, isDecoderRunning){ const decoderRunning = isDecoderRunning() let dbOk = false if (decoder.db) { - try { dbOk = await decoder.db.ping() } catch (_) {} + try { dbOk = await decoder.db.ping() } catch (e) { noteProbeFailure('db_ping', '/live', e) } } const stalled = typeof decoder.isStalled === 'function' ? decoder.isStalled() : false // The parse loop has stopped ITERATING, which every other field here is @@ -126,7 +178,7 @@ function registerLiveRoute(app, decoder, isDecoderRunning){ // autoheal restart-loop a service that is doing useful work and fix nothing. let reorgHalt = { halted: false, reason: null, at: null } if (dbOk && typeof decoder.checkReorgHalt === 'function'){ - try { reorgHalt = await decoder.checkReorgHalt() } catch (_) {} + try { reorgHalt = await decoder.checkReorgHalt() } catch (e) { noteProbeFailure('reorg_halt', '/live', e) } } const syncStatus = decoder.getSyncStatus() const healthy = decoderRunning && dbOk && !stalled && !pollSilent @@ -178,9 +230,27 @@ async function startApi(){ console.log('Decoder parse loop exited; reporting not-running.') decoderRunning = false }).catch((err) => { - console.error('Decoder crashed:', err) decoderRunning = false decoderError = err + // One record, not a record plus a prose twin. A collector reading warn+ + // lines would file the same crash as two separate residue items, and the + // record carries strictly more than the prose line did (message, stack, + // and the halt state below). + // + // The halt state rides the crash record because the two failures look + // identical from outside: an exited container, restart policy cycling it. + // A decoder that aborted a rollback past the dispenser safe-depth window + // needs an operator resync, while an ordinary crash needs a restart, and + // the process is gone before any health route can be asked which it was. + try { + getLogger().error('CRASH', { + kind: 'startFailure', + err: err && err.message ? err.message : String(err), + stack: err && err.stack ? err.stack : undefined, + reorgHalted: decoder.reorgHalted === true, + reorgHaltReason: decoder.reorgHaltReason || null + }) + } catch (_) { /* never mask the crash */ } // A decoder whose start() rejected does no work: the parse loop never runs and // the process would otherwise linger as a permanently-unhealthy but RUNNING // container that `--restart unless-stopped` never recycles. Exit non-zero so the @@ -202,8 +272,40 @@ async function startApi(){ process.on('SIGTERM', shutdown) process.on('SIGINT', shutdown) + // Crash visibility. Registered inside startApi(), not at module scope: several + // unit suites require this module in-process under mocha to reach registerLiveRoute + // and makeRpcBatchGuard, and mocha installs its own handlers. A module-scope + // handler that calls process.exit would abort the whole run instead of failing one + // test. Same placement as xchain-sync/src/api.js. + // + // An uncaughtException leaves the parse loop and the DB pool in an unknown shape + // mid-block, so the process exits after logging and lets the restart policy act. + // An unhandledRejection logs and CONTINUES, which is the choice this file already + // made: a single unresolved promise does not by itself corrupt shared state. + process.on('uncaughtException', (err) => { + try { + getLogger().error('CRASH', { + kind: 'uncaughtException', + err: err && err.message ? err.message : String(err), + stack: err && err.stack ? err.stack : undefined, + reorgHalted: decoder.reorgHalted === true, + reorgHaltReason: decoder.reorgHaltReason || null + }) + } catch (_) { /* never mask the crash */ } + process.exit(1) + }) + process.on('unhandledRejection', (reason) => { - console.error('Unhandled promise rejection:', reason) + const err = reason instanceof Error ? reason : new Error(String(reason)) + try { + getLogger().error('CRASH', { + kind: 'unhandledRejection', + err: err.message, + stack: err.stack, + reorgHalted: decoder.reorgHalted === true, + reorgHaltReason: decoder.reorgHaltReason || null + }) + } catch (_) { /* never mask the rejection */ } }) const app = express(); @@ -278,8 +380,9 @@ async function startApi(){ await decoder.db.ping() dbOk = true dbPhase = 'running' - } catch(_) { + } catch(e) { dbPhase = 'db-unreachable' + noteProbeFailure('db_ping', 'rpc:health', e) } } @@ -292,7 +395,7 @@ async function startApi(){ // own field instead, and let the operator/watchdog act on it. let reorgHalt = { halted: false, reason: null, at: null, checked_at: null } if (dbOk && typeof decoder.checkReorgHalt === 'function'){ - try { reorgHalt = await decoder.checkReorgHalt() } catch (_) {} + try { reorgHalt = await decoder.checkReorgHalt() } catch (e) { noteProbeFailure('reorg_halt', 'rpc:health', e) } } const healthy = decoderRunning && dbOk @@ -396,14 +499,14 @@ async function startApi(){ let dbOk = false if (decoder.db) { // db.ping() uses its own pooled connection; see the health method note. - try { dbOk = await decoder.db.ping() } catch (_) {} + try { dbOk = await decoder.db.ping() } catch (e) { noteProbeFailure('db_ping', '/status', e) } } // Latent halt marker, reported here too so an operator can see it on // the cheap probe. The HTTP code stays keyed on running+db for the reason given // in health() above: a dormant halt must not make an advancing decoder look dead. let reorgHalt = { halted: false, reason: null, at: null, checked_at: null } if (dbOk && typeof decoder.checkReorgHalt === 'function'){ - try { reorgHalt = await decoder.checkReorgHalt() } catch (_) {} + try { reorgHalt = await decoder.checkReorgHalt() } catch (e) { noteProbeFailure('reorg_halt', '/status', e) } } const healthy = decoderRunning && dbOk res.status(healthy ? 200 : 503).json({ @@ -440,4 +543,7 @@ async function startApi(){ // tests without opening a DB connection / listening socket. if (require.main === module) startApi() -module.exports = { makeRpcBatchGuard, registerLiveRoute } \ No newline at end of file +// startApi is exported so the crash handlers it installs can be driven for real +// rather than asserted against the source text; the require.main guard above +// still keeps a plain require from opening a port or a DB connection. +module.exports = { makeRpcBatchGuard, registerLiveRoute, startApi, noteProbeFailure, _resetProbeLogState, _ageProbeLogState, PROBE_LOG_WINDOW_MS } \ No newline at end of file diff --git a/src/db.js b/src/db.js index 49bf14a..2ca87c5 100644 --- a/src/db.js +++ b/src/db.js @@ -21,6 +21,7 @@ const mariadb = require('mariadb'); const fs = require('fs'); const util = require('./util') +const { getLogger } = require('./observability') const SATOSHIS_DECIMALS = 8 const DB_NAME_REGEX = /^[A-Za-z0-9_]+$/ @@ -253,6 +254,15 @@ class Database { // so releaseConnection() (which only releases transactionConnection) // would be a no-op. Release the lease itself, or a fresh-DB boot leaks // one connection per created table plus this one and exhausts the pool. + // + // The swallow is deliberate here and at the eight sibling release sites + // in this file. release() rejects only when the connection is already + // ended or already back in the pool, so there is nothing left to leak and + // nothing an operator would act on; every one of these sits in a finally + // beside a catch that already reports the real cause. A line per site + // would name the same fault twice and spend the log-retention window on + // shutdown noise. The one exception is the temp-table drop in + // deleteAndCompareTxsNotInList, which has a consequence on a LATER query. try { await db.release(); } catch(_){} } console.log('Database and tables verified (' + checked + ' tables, ' + created + ' created).'); @@ -2132,7 +2142,19 @@ class Database { } finally { // Drop the temp table so a pooled connection never leaks it into an // unrelated later query, then release the lease we acquired. - try { await connection.query('DROP TEMPORARY TABLE IF EXISTS ' + TMP) } catch (_) {} + // Unlike the pool-release catches elsewhere in this file, a failed drop + // has a DEFERRED consequence on another query: the temp table rides the + // pooled connection into unrelated work and the next mempool diff fails + // on a table it did not create, with nothing naming the drop that lost. + try { await connection.query('DROP TEMPORARY TABLE IF EXISTS ' + TMP) } + catch (e) { + try { + getLogger().warn('DB_TEMP_TABLE_DROP_FAILED', { + table: TMP, + err: e && e.message ? e.message : String(e) + }) + } catch (_) { /* cleanup must not become the failure */ } + } if (ownLease) { await connection.release() } diff --git a/test/unit/decoderHaltDiagnostics.test.js b/test/unit/decoderHaltDiagnostics.test.js new file mode 100644 index 0000000..f691faf --- /dev/null +++ b/test/unit/decoderHaltDiagnostics.test.js @@ -0,0 +1,290 @@ +// Copyright © 2025–2026 Dankest, LLC +// Based on XChain Platform by Dankest, LLC – https://dankest.llc +// +// SPDX-License-Identifier: AGPL-3.0-or-later +// +// This file is part of XChain Platform. Licensed under the GNU Affero +// General Public License v3.0 or later; see LICENSE.md. A commercial +// license (without AGPL source-disclosure terms) is available - +// contact legal@dankest.llc. + +// Row 4 of the proactive-system-watch spec: the decoder's two silent failure +// shapes become records. +// +// The first is a decoder that decides to halt on a db object with no +// markReorgHalted: no marker is written, so without a record the operator has a +// stopped decoder and every health surface reading a marker that does not exist. +// The second is a health route whose probe throws, which makes a halted decoder +// answer /live and /status with reorg_halted false. +// +// Each case drives the REAL code path (verifyReorg's abort, the real /live +// registrar out of src/api.js) rather than a stand-in, because the claim under +// test is that the site is wired, not that a logger works. + +const assert = require('assert') +const http = require('http') +const express = require('express') +const XChainDecoder = require('../../src/XChainDecoder') +const { + registerLiveRoute, noteProbeFailure, + _resetProbeLogState, _ageProbeLogState, PROBE_LOG_WINDOW_MS +} = require('../../src/api') +const observability = require('../../src/observability') + +// DISPENSER_EXPIRE_SAFE_DEPTH, the rollback ceiling verifyReorg aborts at. +const SAFE_DEPTH = 126 + +let sink + +// getLogger() routes to whatever shipper the process installed, so a capture +// sink on that shipper sees the formatted line with its fields. +function installSink() { + observability._resetObservability() + sink = { lines: [] } + const push = (m) => sink.lines.push(m) + observability.installObservability(null, { + service: 'xchain-decoder', env: {}, + console: { log: push, warn: push, error: push } + }) +} + +function linesFor(event) { + return sink.lines.filter((l) => l.includes(event)) +} + +function makeDecoder() { + return new XChainDecoder( + 'bitcoin-regtest', 'h', '0', 'db', 'u', 'p', 'h', '0', 'u', 'p', false, null + ) +} + +// A decoder holding blocks far above the node's tip, so verifyReorg takes its +// above-tip delete branch and rolls back one block per pass until the +// safe-depth ceiling aborts. The db carries only what that walk reads, so the +// halt these cases assert on is the real one and not a stubbed shortcut. +const NODE_TIP = 100 + +function haltingDecoder(db) { + const decoder = makeDecoder() + let height = 300 + decoder.db = Object.assign({ + getLastBlockIndex: async () => height, + getBlockByIndex: async (i) => (i < 0 ? null : { block_index: i, block_hash: 'aa'.repeat(32) }), + deleteBlockByIndex: async () => { height -= 1; return true } + }, db) + decoder.connector = { rpcErrors: 0 } + return decoder +} + +describe('REORG_HALT: a halt the marker cannot record still leaves a record', function () { + + beforeEach(function () { installSink() }) + afterEach(function () { observability._resetObservability() }) + + it('emits REORG_HALT with reason and depth when db.markReorgHalted is missing', async function () { + // The db deliberately has no markReorgHalted: this is the bare return. + const decoder = haltingDecoder({}) + await assert.rejects(() => decoder.verifyReorg(NODE_TIP), /safe-depth/) + + const halts = linesFor('REORG_HALT') + assert.strictEqual(halts.length, 1, 'the halt must produce exactly one record') + const line = halts[0] + assert.ok(line.includes(' error '), 'REORG_HALT is an error-level event: ' + line) + assert.ok(line.includes('coin=BTC'), 'the record must name the coin: ' + line) + assert.ok(line.includes('network=regtest'), 'the record must name the network: ' + line) + assert.ok(line.includes('depth=' + SAFE_DEPTH), + 'the record must carry the depth it was about to persist: ' + line) + assert.ok(/reason="[^"]*safe-depth[^"]*"/.test(line), + 'the record must carry the reason it was about to persist: ' + line) + assert.ok(line.includes('marker_persisted=false'), + 'the record must say the marker could not be written: ' + line) + assert.ok(line.includes('/status') && line.includes('/live'), + 'the record must say which surfaces will NOT report the halt: ' + line) + }) + + it('still emits REORG_HALT on the normal path, and says the marker was written', async function () { + let marked = null + const decoder = haltingDecoder({ markReorgHalted: async (r) => { marked = r } }) + await assert.rejects(() => decoder.verifyReorg(NODE_TIP), /safe-depth/) + + const halts = linesFor('REORG_HALT') + assert.strictEqual(halts.length, 1) + assert.ok(halts[0].includes('marker_persisted=true'), halts[0]) + assert.ok(marked && /safe-depth/.test(marked), 'the durable marker is still written') + }) + + it('reports the halt in memory even when nothing durable can be written', async function () { + const decoder = haltingDecoder({}) + await assert.rejects(() => decoder.verifyReorg(NODE_TIP), /safe-depth/) + assert.strictEqual(decoder.reorgHalted, true) + assert.match(decoder.reorgHaltReason, /safe-depth/) + }) +}) + +describe('health probes: a failing probe stops being silent', function () { + + beforeEach(function () { installSink(); _resetProbeLogState() }) + afterEach(function () { observability._resetObservability(); _resetProbeLogState() }) + + function liveApp(decoder, running = true) { + const app = express() + registerLiveRoute(app, decoder, () => running) + return app + } + + function getLive(app) { + return new Promise((resolve, reject) => { + const server = app.listen(0, () => { + http.get({ port: server.address().port, path: '/live' }, (res) => { + let body = '' + res.on('data', (c) => { body += c }) + res.on('end', () => { + server.close() + resolve({ status: res.statusCode, body: JSON.parse(body) }) + }) + }).on('error', (e) => { server.close(); reject(e) }) + }) + }) + } + + // A decoder that is otherwise entirely healthy, so the only thing a case can + // be reading is the probe it breaks. + function probeDecoder() { + const decoder = makeDecoder() + decoder.lastProcessedBlockIndex = 150 + decoder.blockchainInfoLastBlock = 150 + decoder.blockchainInfoLastRefreshAt = Date.now() + decoder.lastAdvanceAt = Date.now() + decoder.lastPollAt = Date.now() + decoder.synced = true + decoder.db = { ping: async () => true } + decoder.connector = { rpcErrors: 0 } + return decoder + } + + it('names the db_ping probe on /live when the ping throws', async function () { + const decoder = probeDecoder() + decoder.db = { ping: async () => { throw new Error('pool timeout acquiring connection') } } + + const res = await getLive(liveApp(decoder)) + // Control: the route still answers, with the code it always answered. + assert.strictEqual(res.status, 503) + assert.strictEqual(res.body.db, false) + + const warned = linesFor('HEALTH_PROBE_FAILED') + assert.strictEqual(warned.length, 1, 'the failure must produce one record') + assert.ok(warned[0].includes(' warn '), warned[0]) + assert.ok(warned[0].includes('probe=db_ping'), warned[0]) + assert.ok(warned[0].includes('route=/live'), warned[0]) + assert.ok(warned[0].includes('pool timeout'), 'the cause rides the record: ' + warned[0]) + }) + + it('names the reorg_halt probe on /live, the failure that makes a halted decoder read clean', async function () { + const decoder = probeDecoder() + decoder.checkReorgHalt = async () => { throw new Error('events table is gone') } + + const res = await getLive(liveApp(decoder)) + // The wrong-but-alive shape this exists for: the route reports no halt + // because it could not ask, and that is now the difference between a + // silent lie and a warned one. + assert.strictEqual(res.status, 200) + assert.strictEqual(res.body.reorg_halted, false) + + const warned = linesFor('HEALTH_PROBE_FAILED') + assert.strictEqual(warned.length, 1) + assert.ok(warned[0].includes('probe=reorg_halt'), warned[0]) + assert.ok(warned[0].includes('route=/live'), warned[0]) + assert.ok(warned[0].includes('events table is gone'), warned[0]) + }) + + it('throttles a repeating probe failure to one line per window and counts the rest', async function () { + const decoder = probeDecoder() + decoder.db = { ping: async () => { throw new Error('pool timeout') } } + const app = liveApp(decoder) + + for (let i = 0; i < 5; i++) await getLive(app) + assert.strictEqual(linesFor('HEALTH_PROBE_FAILED').length, 1, + 'a caller-driven route must not turn one outage into one line per request') + + // Age the window rather than sleeping through it, so the suppressed count + // the next line has to report survives. + _ageProbeLogState() + await getLive(app) + const warned = linesFor('HEALTH_PROBE_FAILED') + assert.strictEqual(warned.length, 2) + assert.ok(warned[1].includes('suppressed=4'), + 'a throttled flood must stay countable, not merely quiet: ' + warned[1]) + assert.ok(PROBE_LOG_WINDOW_MS > 0, 'the window is a real duration, not a disabled guard') + }) + + it('carries a cause even when the probe threw something that is not an Error', function () { + noteProbeFailure('db_ping', '/status', 'ECONNREFUSED') + const warned = linesFor('HEALTH_PROBE_FAILED') + assert.strictEqual(warned.length, 1) + assert.ok(warned[0].includes('err=ECONNREFUSED'), warned[0]) + }) + + it('answers null instead of throwing when the error itself cannot be read', function () { + // A diagnostic that throws inside a health route would turn a reportable + // probe failure into a 500 on the route the healthcheck polls. + const hostile = { get message() { throw new Error('unreadable') } } + assert.strictEqual(noteProbeFailure('db_ping', '/live', hostile), null) + assert.strictEqual(linesFor('HEALTH_PROBE_FAILED').length, 0) + }) + + it('keeps the two probes on separate throttles, so one failure cannot mask the other', async function () { + const decoder = probeDecoder() + decoder.db = { ping: async () => { throw new Error('pool timeout') } } + decoder.checkReorgHalt = async () => { throw new Error('events table is gone') } + + await getLive(liveApp(decoder)) + // db_ping fails first, so dbOk is false and the halt probe is not reached + // on this route. Drive the halt probe with a working ping. + decoder.db = { ping: async () => true } + await getLive(liveApp(decoder)) + + const warned = linesFor('HEALTH_PROBE_FAILED') + assert.strictEqual(warned.length, 2) + assert.ok(warned.some((l) => l.includes('probe=db_ping'))) + assert.ok(warned.some((l) => l.includes('probe=reorg_halt'))) + }) +}) + +// The one db.js catch worth a line. The other nine swallow a failed pool release, +// which happens only when the connection is already gone and always sits beside a +// catch that reported the real cause. This one loses a temp table on a POOLED +// connection, so the consequence lands on an unrelated later query with nothing +// naming the drop that failed. +describe('db: a failed temp-table drop stops being silent', function () { + + const Database = require('../../src/db.js') + + beforeEach(function () { installSink() }) + afterEach(function () { observability._resetObservability() }) + + function poolWhoseDropFails() { + const conn = { + query: async (sql) => { + if (/DROP\s+TEMPORARY\s+TABLE/i.test(sql)) throw new Error('lost connection to server') + if (/SELECT\s+s\.tx_hash/i.test(sql)) return [] + return { affectedRows: 0 } + }, + release: async () => {} + } + return { getConnection: async () => conn } + } + + it('records the drop failure with the table and the cause', async function () { + const db = new Database('127.0.0.1', 3306, 'xchain_btc_regtest', 'u', 'p') + db.pool = poolWhoseDropFails() + + // Control: the drop is cleanup, so the call still returns its result. + const r = await db.deleteAndCompareTxsNotInList([]) + assert.strictEqual(r.transactionsDeleted, 0) + + const warned = linesFor('DB_TEMP_TABLE_DROP_FAILED') + assert.strictEqual(warned.length, 1) + assert.ok(warned[0].includes('table=_mempool_node_snapshot'), warned[0]) + assert.ok(warned[0].includes('lost connection to server'), warned[0]) + }) +}) From 26a3ae815f42fc9732abefa27909ea01294a6219 Mon Sep 17 00:00:00 2001 From: J-Dog Date: Sun, 30 Aug 2026 10:04:48 -0700 Subject: [PATCH 5/7] feat(rollcall): decode ROLLCALL from the wire Adds ROLLCALL to VALID_ACTION_NAMES and re-vendors the action manifest. Without it every roll call on DOGE is dropped at decode, silently, which would evict the whole federation once the BTC close starts asking. Allowlist is 36 and identical to the manifest wireDecoded set. Suite: 1426 passing, 11 pending, 0 failing. --- src/XChainDecoder.js | 3 ++- test/fixtures/action-manifest.json | 6 ++++++ 2 files changed, 8 insertions(+), 1 deletion(-) diff --git a/src/XChainDecoder.js b/src/XChainDecoder.js index d07dd4f..4854829 100644 --- a/src/XChainDecoder.js +++ b/src/XChainDecoder.js @@ -187,7 +187,8 @@ const VALID_ACTION_NAMES = new Set([ 'BATCH', 'BET', 'BROADCAST', 'CALLBACK', 'COINPAY', 'COLLECT', 'DELEGATE', 'DEPLOY', 'DEPOSIT', 'DESTROY', 'DISPENSER', 'DIVIDEND', 'EXECUTE', 'FILE', 'ISSUE', 'LINK', 'LIST', 'MESSAGE', 'MINT', - 'NODEPROOF', 'ORDER', 'PRICE', 'SEND', 'SLASH', 'SLEEP', 'STAKE', 'SWAP', + 'NODEPROOF', 'ORDER', 'PRICE', 'ROLLCALL', 'SEND', 'SLASH', 'SLEEP', 'STAKE', + 'SWAP', 'SWEEP', 'UNSTAKE', 'VOTE', 'WITHDRAW' ]) diff --git a/test/fixtures/action-manifest.json b/test/fixtures/action-manifest.json index 3d0cff0..93e02ab 100644 --- a/test/fixtures/action-manifest.json +++ b/test/fixtures/action-manifest.json @@ -312,6 +312,12 @@ "explorerRender": true, "walletForm": true }, + "ROLLCALL": { + "category": "validator", + "wireDecoded": true, + "indexerHandled": true, + "explorerRender": true + }, "SEND": { "category": "wire-user", "wireDecoded": true, From 040a7f30787cd7505a26c6ec896a1ff0e50535de Mon Sep 17 00:00:00 2001 From: J-Dog Date: Sun, 30 Aug 2026 18:00:47 -0700 Subject: [PATCH 6/7] observability: re-vendor the shared log shim so one console call is one line Picks up the canonical fix: a trailing error argument expanded across lines and only the first line carried the timestamp, level and service, leaving every line after it an orphan with no operation, no error and no coin. The breaks are escaped now; the stack still ships on one line. Vendored copy, not edited here. Behaviour changes belong in the canonical module first. --- src/observability/logShipper.js | 15 ++++++++++++++- 1 file changed, 14 insertions(+), 1 deletion(-) diff --git a/src/observability/logShipper.js b/src/observability/logShipper.js index d232afa..656141a 100644 --- a/src/observability/logShipper.js +++ b/src/observability/logShipper.js @@ -109,7 +109,20 @@ function formatFieldValue(value) { * every console.error line and page the fleet on first deploy. */ function formatTextLine(record) { - let line = `${record.ts} ${record.level} [${record.service}] ${record.msg}`; + // ONE console call is ONE line. A trailing Error (or any object) expands across + // lines under util.inspect, and only the FIRST line carries the timestamp, level + // and service - every continuation is an orphan. Measured on the live fleet: + // ` fatal: true,` appeared six times in the hub and three in each indexer, + // naming no operation, no error and no coin, because it was the middle of a + // pretty-printed mariadb SqlError. Those fragments are unparseable by anything + // keying on the prefix, which is every consumer of these logs. + // + // Escape the breaks rather than emit them. Nothing is lost: the stack still + // ships, on one line, exactly as formatFieldValue already renders a `stack` + // field. JSON mode needs no equivalent - JSON.stringify escapes newlines, so + // an NDJSON record is one physical line already and keeps the true characters. + const msg = String(record.msg).replace(/\r\n|\r|\n/g, '\\n'); + let line = `${record.ts} ${record.level} [${record.service}] ${msg}`; for (const [k, v] of Object.entries(record)) { if (ENVELOPE_KEYS.has(k) || v === undefined) continue; line += ` ${String(k).replace(/[\s"'=]/g, '_')}=${formatFieldValue(v)}`; From b0aaad563e2c4e65c05139cd812443eaaa0e8abf Mon Sep 17 00:00:00 2001 From: J-Dog Date: Sun, 30 Aug 2026 19:25:41 -0700 Subject: [PATCH 7/7] release: 0.12.0 --- CHANGELOG.md | 13 +++++++++++++ package-lock.json | 29 ++++++++++++++++------------- package.json | 4 ++-- 3 files changed, 31 insertions(+), 15 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1e0396d..6ba2e9d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,19 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [0.12.0] - 2026-08-30 + +### Added +- ROLLCALL is decoded from the wire. + +### Fixed +- The MariaDB connector moves to 3.5.3, closing three high-severity advisories against the pinned 3.5.2. +- RPC faults keep their identity, and tuning environment variables go through the shared validator. +- A halt the service cannot record no longer passes unnoticed. + +### Changed +- Service logging routes through the shared log shim, one line per console call. + ## [0.11.0] - 2026-08-25 ### Added diff --git a/package-lock.json b/package-lock.json index d9c677d..20107f1 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "xchain-decoder", - "version": "0.11.0", + "version": "0.12.0", "lockfileVersion": 3, "requires": true, "packages": { "": { "name": "xchain-decoder", - "version": "0.11.0", + "version": "0.12.0", "license": "AGPL-3.0-or-later", "dependencies": { "axios": "^1.18.1", @@ -24,7 +24,7 @@ "helmet": "^8.2.0", "leveldown": "^6.1.1", "levelup": "^5.1.1", - "mariadb": "3.5.2", + "mariadb": "3.5.3", "memdown": "^6.1.1", "tiny-secp256k1": "2.2.4" }, @@ -3915,19 +3915,19 @@ } }, "node_modules/mariadb": { - "version": "3.5.2", - "resolved": "https://registry.npmjs.org/mariadb/-/mariadb-3.5.2.tgz", - "integrity": "sha512-9rztrI4nouxAY/82a+RlzzZ5ie2vxu2eYclkBvTy1ATXH1B9cnvZ0O71Pzsy/mlfDb5P3HhOg0JzQKkDRhctyA==", + "version": "3.5.3", + "resolved": "https://registry.npmjs.org/mariadb/-/mariadb-3.5.3.tgz", + "integrity": "sha512-i053Kc0MgdUv/hu9mCyq67TYfPXFj3/MV8I7ZW5wvJNixIyXC0VztMPUjIVj/449nQo+BsxFD4Fdk/sA/uqKPQ==", "license": "LGPL-2.1-or-later", "dependencies": { "@types/geojson": "^7946.0.16", - "@types/node": ">=18", + "@types/node": ">=20", "denque": "^2.1.0", "iconv-lite": "^0.7.2", - "lru-cache": "^10.4.3" + "lru-cache": "^11.5.0" }, "engines": { - "node": ">= 18" + "node": ">= 20.0.0" } }, "node_modules/mariadb/node_modules/@types/node": { @@ -3939,10 +3939,13 @@ } }, "node_modules/mariadb/node_modules/lru-cache": { - "version": "10.4.3", - "resolved": "https://registry.npmjs.org/lru-cache/-/lru-cache-10.4.3.tgz", - "integrity": "sha512-JNAzZcXrCt42VGLuYz0zfAzDfAvJWW6AfYlDBQyDV5DClI2m5sAmK+OIO7s59XfsRsWHp02jAJrRadPRGTt6SQ==", - "license": "ISC" + "version": "11.5.2", + "resolved": "https://registry.npmjs.org/lru-cache/-/lru-cache-11.5.2.tgz", + "integrity": "sha512-4pfM1Ff0x50o0tQwb5ucw/RzNyD0/YJME6IVcStalZuMWxdt3sR3huStTtxz4PUmvZfRguvDejasvQ2kifR11g==", + "license": "BlueOak-1.0.0", + "engines": { + "node": "20 || >=22" + } }, "node_modules/mariadb/node_modules/undici-types": { "version": "7.16.0", diff --git a/package.json b/package.json index a72c194..1246606 100644 --- a/package.json +++ b/package.json @@ -1,7 +1,7 @@ { "name": "xchain-decoder", "description": "xchain-decoder decodes XChain platform transactions from a given blockchain and populates a database with the decoded data.", - "version": "0.11.0", + "version": "0.12.0", "license": "AGPL-3.0-or-later", "repository": { "type": "git", @@ -23,7 +23,7 @@ "helmet": "^8.2.0", "leveldown": "^6.1.1", "levelup": "^5.1.1", - "mariadb": "3.5.2", + "mariadb": "3.5.3", "memdown": "^6.1.1", "tiny-secp256k1": "2.2.4" },