Add logging (#140)

We want to add logging to the RPC layer in the extension to help with debugging while writing tests. This helps us achieve that.
MetaMask · Aug 22, 2022 · 147090e · 147090e
1 parent 9e305fe
commit 147090e
Show file tree

Hide file tree

Showing 8 changed files with 96 additions and 2 deletions.
diff --git 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
@@ -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');
 // `<nil>` comes from https://github.com/ethereum/go-ethereum/issues/16925
 const emptyValues = [undefined, null, '\u003cnil\u003e'];
 
@@ -178,15 +180,22 @@ export function createBlockCacheMiddleware({
       blockTag = 'latest';
     }
 
+    log('blockTag = %o, req = %o', blockTag, req);
+
     // get exact block number
     let requestedBlockNumber: string;
     if (blockTag === 'earliest') {
       // this just exists for symmetry with "latest"
       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
@@ -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<Block> = await pify(
       (provider as SafeEventEmitterProvider).sendAsync,
     ).call(provider, childRequest);

diff --git 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
@@ -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,18 +39,29 @@ 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;
     }
     // setup response handler array for subsequent requests
     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
@@ -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
@@ -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
 // `<nil>` 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<Block> = await retry(
       10,
       async () => {
+        log('Performing another request %o', childRequest);
         const attemptResponse: PendingJsonRpcResponse<Block> = 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
@@ -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/[email protected]":
   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 @@ [email protected]:
   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"