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/README.md b/README.md index 43ae2a8..3445870 100644 --- a/README.md +++ b/README.md @@ -4,7 +4,7 @@ # XChain Platform Decoder

- Version + Version Tests Node License @@ -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/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" }, 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..4854829 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') @@ -182,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' ]) @@ -726,31 +732,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 +790,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 +961,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 +994,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 +1029,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] @@ -1743,7 +1762,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) { @@ -2032,11 +2076,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..b4179f6 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'); @@ -30,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 @@ -92,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 @@ -102,6 +165,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 (e) { noteProbeFailure('reorg_halt', '/live', e) } + } const syncStatus = decoder.getSyncStatus() const healthy = decoderRunning && dbOk && !stalled && !pollSilent res.status(healthy ? 200 : 503).json({ @@ -111,6 +189,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 @@ -149,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 @@ -173,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(); @@ -249,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) } } @@ -263,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 @@ -367,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({ @@ -411,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/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..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_]+$/ @@ -46,6 +47,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)) { @@ -227,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).'); @@ -714,6 +750,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 +897,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 +953,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 +985,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 +996,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; } @@ -2102,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/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/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..656141a 100644 --- a/src/observability/logShipper.js +++ b/src/observability/logShipper.js @@ -47,13 +47,87 @@ 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) { + // 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)}`; + } + return line; } // Depth-limited so a cyclic or huge object cannot stall the hot path; anything @@ -181,7 +255,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 +265,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 +346,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/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, 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/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]) + }) +}) 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/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 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); + }); +});