diff --git a/package.json b/package.json index 7f6715ef..1b77bfb9 100644 --- a/package.json +++ b/package.json @@ -37,6 +37,7 @@ }, "dependencies": { "@metamask/safe-event-emitter": "^2.0.0", + "@metamask/utils": "^3.0.1", "btoa": "^1.2.1", "clone": "^2.1.1", "eth-block-tracker": "^5.0.1", diff --git a/src/block-cache.ts b/src/block-cache.ts index 28c41d3b..430ee7a1 100644 --- a/src/block-cache.ts +++ b/src/block-cache.ts @@ -1,5 +1,6 @@ import { PollingBlockTracker } from 'eth-block-tracker'; import { createAsyncMiddleware, JsonRpcMiddleware } from 'json-rpc-engine'; +import { projectLogger, createModuleLogger } from './logging-utils'; import { cacheIdentifierForPayload, blockTagForPayload, @@ -14,6 +15,7 @@ import type { JsonRpcRequestToCache, } from './types'; +const log = createModuleLogger(projectLogger, 'block-cache'); // `` comes from https://github.com/ethereum/go-ethereum/issues/16925 const emptyValues = [undefined, null, '\u003cnil\u003e']; @@ -178,6 +180,8 @@ export function createBlockCacheMiddleware({ blockTag = 'latest'; } + log('blockTag = %o, req = %o', blockTag, req); + // get exact block number let requestedBlockNumber: string; if (blockTag === 'earliest') { @@ -185,8 +189,13 @@ export function createBlockCacheMiddleware({ requestedBlockNumber = '0x00'; } else if (blockTag === 'latest') { // fetch latest block number + log('Fetching latest block number to determine cache key'); const latestBlockNumber = await blockTracker.getLatestBlock(); // clear all cache before latest block + log( + 'Clearing values stored under block numbers before %o', + latestBlockNumber, + ); blockCache.clearBefore(latestBlockNumber); requestedBlockNumber = latestBlockNumber; } else { @@ -201,15 +210,24 @@ export function createBlockCacheMiddleware({ if (cacheResult === undefined) { // cache miss // wait for other middleware to handle request + log( + 'No cache stored under block number %o, carrying request forward', + requestedBlockNumber, + ); // eslint-disable-next-line node/callback-return await next(); // add result to cache // it's safe to cast res.result as Block, due to runtime type checks // performed when strategy.set is called + log('Populating cache with', res); await strategy.set(req, requestedBlockNumber, res.result as Block); } else { // fill in result from cache + log( + 'Cache hit, reusing cache result stored under block number %o', + requestedBlockNumber, + ); res.result = cacheResult; } return undefined; diff --git a/src/block-ref.ts b/src/block-ref.ts index 4fdad7d1..a7c1727a 100644 --- a/src/block-ref.ts +++ b/src/block-ref.ts @@ -6,6 +6,7 @@ import { } from 'json-rpc-engine'; import clone from 'clone'; import pify from 'pify'; +import { projectLogger, createModuleLogger } from './logging-utils'; import { blockTagParamIndex } from './utils/cache'; import type { Block, SafeEventEmitterProvider } from './types'; @@ -14,6 +15,8 @@ interface BlockRefMiddlewareOptions { provider?: SafeEventEmitterProvider; } +const log = createModuleLogger(projectLogger, 'block-ref'); + export function createBlockRefMiddleware({ provider, blockTracker, @@ -42,6 +45,7 @@ export function createBlockRefMiddleware({ } if (blockRef !== 'latest') { + log('blockRef is not "latest", carrying request forward'); return next(); } // lookup latest block @@ -52,6 +56,7 @@ export function createBlockRefMiddleware({ childRequest.params[blockRefIndex] = latestBlockNumber; } // perform child request + log('Performing another request %o', childRequest); const childRes: PendingJsonRpcResponse = await pify( (provider as SafeEventEmitterProvider).sendAsync, ).call(provider, childRequest); diff --git a/src/block-tracker-inspector.ts b/src/block-tracker-inspector.ts index 6e5277f4..ed032abf 100644 --- a/src/block-tracker-inspector.ts +++ b/src/block-tracker-inspector.ts @@ -1,7 +1,9 @@ import { PollingBlockTracker } from 'eth-block-tracker'; import { createAsyncMiddleware, JsonRpcMiddleware } from 'json-rpc-engine'; +import { projectLogger, createModuleLogger } from './logging-utils'; import type { Block } from './types'; +const log = createModuleLogger(projectLogger, 'block-tracker-inspector'); const futureBlockRefRequests: string[] = [ 'eth_getTransactionByHash', 'eth_getTransactionReceipt', @@ -26,6 +28,8 @@ export function createBlockTrackerInspectorMiddleware({ return undefined; } + log('res.result.blockNumber exists, proceeding. res = %o', res); + if (typeof res.result.blockNumber === 'string') { // if number is higher, suggest block-tracker check for a new block const blockNumber: number = Number.parseInt(res.result.blockNumber, 16); @@ -35,6 +39,9 @@ export function createBlockTrackerInspectorMiddleware({ 16, ); if (blockNumber > currentBlockNumber) { + log( + 'blockNumber from response is greater than current block number, refreshing current block number', + ); await blockTracker.checkForLatestBlock(); } } diff --git a/src/inflight-cache.ts b/src/inflight-cache.ts index a4a42412..ad193019 100644 --- a/src/inflight-cache.ts +++ b/src/inflight-cache.ts @@ -4,6 +4,7 @@ import { JsonRpcMiddleware, PendingJsonRpcResponse, } from 'json-rpc-engine'; +import { projectLogger, createModuleLogger } from './logging-utils'; import { cacheIdentifierForPayload } from './utils/cache'; import type { Block, JsonRpcRequestToCache } from './types'; @@ -12,6 +13,8 @@ interface InflightRequest { [cacheId: string]: RequestHandlers[]; } +const log = createModuleLogger(projectLogger, 'inflight-cache'); + export function createInflightCacheMiddleware(): JsonRpcMiddleware< string[], Block @@ -27,6 +30,7 @@ export function createInflightCacheMiddleware(): JsonRpcMiddleware< const cacheId: string | null = cacheIdentifierForPayload(req); // if not cacheable, skip if (!cacheId) { + log('Request is not cacheable, proceeding. req = %o', req); return next(); } // check for matching requests @@ -35,6 +39,11 @@ export function createInflightCacheMiddleware(): JsonRpcMiddleware< if (activeRequestHandlers) { // setup the response listener and wait for it to be called // it will handle copying the result and request fields + log( + 'Running %i handler(s) for request %o', + activeRequestHandlers.length, + req, + ); await createActiveRequestHandler(res, activeRequestHandlers); return undefined; } @@ -42,11 +51,17 @@ export function createInflightCacheMiddleware(): JsonRpcMiddleware< activeRequestHandlers = []; inflightRequests[cacheId] = activeRequestHandlers; // allow request to be handled normally + log('Carrying original request forward %o', req); // eslint-disable-next-line node/callback-return await next(); // clear inflight requests delete inflightRequests[cacheId]; // schedule activeRequestHandlers to be handled + log( + 'Running %i collected handler(s) for request %o', + activeRequestHandlers.length, + req, + ); handleActiveRequest(res, activeRequestHandlers); // complete return undefined; diff --git a/src/logging-utils.ts b/src/logging-utils.ts new file mode 100644 index 00000000..fd98eea1 --- /dev/null +++ b/src/logging-utils.ts @@ -0,0 +1,5 @@ +import { createProjectLogger, createModuleLogger } from '@metamask/utils'; + +export const projectLogger = createProjectLogger('eth-json-rpc-middleware'); + +export { createModuleLogger }; diff --git a/src/retryOnEmpty.ts b/src/retryOnEmpty.ts index e66a60ba..4d29f133 100644 --- a/src/retryOnEmpty.ts +++ b/src/retryOnEmpty.ts @@ -6,6 +6,7 @@ import { PendingJsonRpcResponse, } from 'json-rpc-engine'; import pify from 'pify'; +import { projectLogger, createModuleLogger } from './logging-utils'; import { blockTagParamIndex } from './utils/cache'; import { Block, SafeEventEmitterProvider } from './types'; @@ -16,6 +17,7 @@ import { Block, SafeEventEmitterProvider } from './types'; // nodes that are not always in sync with each other. // +const log = createModuleLogger(projectLogger, 'retry-on-empty'); // empty values used to determine if a request should be retried // `` comes from https://github.com/ethereum/go-ethereum/issues/16925 const emptyValues: (string | null | undefined)[] = [ @@ -75,17 +77,31 @@ export function createRetryOnEmptyMiddleware({ ); // skip if request block number is higher than current if (blockRefNumber > latestBlockNumber) { + log( + 'Requested block number %o is higher than latest block number %o, falling through to original request', + blockRefNumber, + latestBlockNumber, + ); return next(); } + + log( + 'Requested block number %o is not higher than latest block number %o, retrying request until non-empty response is received', + blockRefNumber, + latestBlockNumber, + ); + // create child request with specific block-ref const childRequest = clone(req); // attempt child request until non-empty response is received const childResponse: PendingJsonRpcResponse = await retry( 10, async () => { + log('Performing another request %o', childRequest); const attemptResponse: PendingJsonRpcResponse = await pify( (provider as SafeEventEmitterProvider).sendAsync, ).call(provider, childRequest); + log('Response is %o', attemptResponse); // verify result if (emptyValues.includes(attemptResponse as any)) { throw new Error( diff --git a/yarn.lock b/yarn.lock index 1ef62aa4..f3449559 100644 --- a/yarn.lock +++ b/yarn.lock @@ -754,6 +754,16 @@ resolved "https://registry.yarnpkg.com/@metamask/safe-event-emitter/-/safe-event-emitter-2.0.0.tgz#af577b477c683fad17c619a78208cede06f9605c" integrity sha512-/kSXhY692qiV1MXu6EeOZvg5nECLclxNXcKCxJ3cXQgYuRymRHpdx/t7JXfsK+JLjwA1e1c1/SBrlQYpusC29Q== +"@metamask/utils@^3.0.1": + version "3.0.1" + resolved "https://registry.yarnpkg.com/@metamask/utils/-/utils-3.0.1.tgz#53ed2b9cbbd12b18c1db6929728446633d6a74c4" + integrity sha512-FDWQ+MeeWQh0b/w2D50+oVPrRqUIvawDlPia+EH9NCOFN0Ty3KkzkQXfO6FgHKMyR4aWuS4SBOrhWFRW8km6lQ== + dependencies: + "@types/debug" "^4.1.7" + debug "^4.3.4" + fast-deep-equal "^3.1.3" + superstruct "^0.16.0" + "@nodelib/fs.scandir@2.1.4": version "2.1.4" resolved "https://registry.yarnpkg.com/@nodelib/fs.scandir/-/fs.scandir-2.1.4.tgz#d4b3549a5db5de2683e0c1071ab4f140904bbf69" @@ -900,6 +910,13 @@ resolved "https://registry.yarnpkg.com/@types/clone/-/clone-2.1.0.tgz#cb888a3fe5319275b566ae3a9bc606e310c533d4" integrity sha512-d/aS/lPOnUSruPhgNtT8jW39fHRVTLQy9sodysP1kkG8EdAtdZu1vt8NJaYA8w/6Z9j8izkAsx1A/yJhcYR1CA== +"@types/debug@^4.1.7": + version "4.1.7" + resolved "https://registry.yarnpkg.com/@types/debug/-/debug-4.1.7.tgz#7cc0ea761509124709b8b2d1090d8f6c17aadb82" + integrity sha512-9AonUzyTjXXhEOa0DnqpzZi6VHlqKMswga9EXjpXnnqxwLtdvPPtlO8evrI5D9S6asFRCQ6v+wpiUKbw+vKqyg== + dependencies: + "@types/ms" "*" + "@types/eth-sig-util@^2.1.0": version "2.1.0" resolved "https://registry.yarnpkg.com/@types/eth-sig-util/-/eth-sig-util-2.1.0.tgz#54497e9c01b5ee3a60475686cce1a20ddccc358b" @@ -969,6 +986,11 @@ resolved "https://registry.yarnpkg.com/@types/minimatch/-/minimatch-3.0.5.tgz#1001cc5e6a3704b83c236027e77f2f58ea010f40" integrity sha512-Klz949h02Gz2uZCMGwDUSDS1YBlTdDDgbWHi+81l29tQALUtvz4rAYi5uoVhE5Lagoq6DeqAUlbrHvW/mXDgdQ== +"@types/ms@*": + version "0.7.31" + resolved "https://registry.yarnpkg.com/@types/ms/-/ms-0.7.31.tgz#31b7ca6407128a3d2bbc27fe2d21b345397f6197" + integrity sha512-iiUgKzV9AuaEkZqkOLDIvlQiL6ltuZd9tGcW3gwpnX8JbuiuhFlEGmmFXEXkN50Cvq7Os88IY2v0dkDqXYWVgA== + "@types/node@*": version "14.14.20" resolved "https://registry.yarnpkg.com/@types/node/-/node-14.14.20.tgz#f7974863edd21d1f8a494a73e8e2b3658615c340" @@ -2864,7 +2886,7 @@ debug@3.2.6: dependencies: ms "^2.1.1" -debug@4, debug@^4.1.0: +debug@4, debug@^4.1.0, debug@^4.3.4: version "4.3.4" resolved "https://registry.yarnpkg.com/debug/-/debug-4.3.4.tgz#1319f6579357f2338d3337d2cdd4914bb5dcc865" integrity sha512-PRWFHuSU3eDtQJPvnNY7Jcket1j0t5OuOsFzPPzsekD52Zl8qUfFIPEiswXqIvHWGVHOgX+7G/vCNNhehwxfkQ== @@ -4152,7 +4174,7 @@ fake-merkle-patricia-tree@^1.0.1: dependencies: checkpoint-store "^1.1.0" -fast-deep-equal@^3.1.1: +fast-deep-equal@^3.1.1, fast-deep-equal@^3.1.3: version "3.1.3" resolved "https://registry.yarnpkg.com/fast-deep-equal/-/fast-deep-equal-3.1.3.tgz#3a7d56b559d6cbc3eb512325244e619a65c6c525" integrity sha512-f3qQ9oQy9j2AhBe/H9VC91wLmKBCCU/gDOnKNAYG5hswO7BLKj09Hc5HYNz9cGI++xlpDCIgDaitVs03ATR84Q== @@ -8417,6 +8439,11 @@ strip-json-comments@^3.1.0, strip-json-comments@^3.1.1: resolved "https://registry.yarnpkg.com/strip-json-comments/-/strip-json-comments-3.1.1.tgz#31f1281b3832630434831c310c01cccda8cbe006" integrity sha512-6fPc+R4ihwqP6N/aIv2f1gMH8lOVtWQHoqC4yK6oSDVVocumAsfCqjkXnqiYMhmMwS/mEHLp7Vehlt3ql6lEig== +superstruct@^0.16.0: + version "0.16.0" + resolved "https://registry.yarnpkg.com/superstruct/-/superstruct-0.16.0.tgz#9af5e059acd08e774789ad8880962427ef68dace" + integrity sha512-IDQtwnnlaan1NhuHqyD/U11lROYvCQ79JyfwlFU9xEVHzqV/Ys/RrwmHPCG0CVH/1g0BuodEjH1msxK2UHxehA== + supports-color@^2.0.0: version "2.0.0" resolved "https://registry.yarnpkg.com/supports-color/-/supports-color-2.0.0.tgz#535d045ce6b6363fa40117084629995e9df324c7"