From e0fc934112d5b66ea28401fff524bc0683fe0b28 Mon Sep 17 00:00:00 2001 From: "Siyu Jiang (See-You John)" <91580504+jsy1218@users.noreply.github.com> Date: Thu, 18 Jul 2024 13:11:39 -0700 Subject: [PATCH] chore: add RPC requests logging for RETH calls slower than GETH (#785) * chore: add RPC requests logging for RETH calls slower than GETH * switch-cae * fix unit test --- lib/rpc/SingleJsonRpcProvider.ts | 100 +++++++++++++++--- lib/rpc/UniJsonRpcProvider.ts | 2 +- .../mocha/unit/rpc/UniJsonRpcProvider.test.ts | 20 ++-- 3 files changed, 94 insertions(+), 28 deletions(-) diff --git a/lib/rpc/SingleJsonRpcProvider.ts b/lib/rpc/SingleJsonRpcProvider.ts index ae086b5f1e..a0e52efcc1 100644 --- a/lib/rpc/SingleJsonRpcProvider.ts +++ b/lib/rpc/SingleJsonRpcProvider.ts @@ -178,12 +178,25 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { } } - async evaluateLatency(methodName: string, ...args: any[]) { + async evaluateLatency(latency: number, methodName: string, ...args: any[]) { this.log.debug(`${this.url}: Evaluate for latency... methodName: ${methodName}`) this.logEvaluateLatency() this.evaluatingLatency = true try { - return await (this as any)[`${methodName}_EvaluateLatency`](...args) + switch (methodName) { + case CALL_METHOD_NAME: + const transaction: Deferrable = args[0] + const blockTag: BlockTag | Promise = args[1] + + return await this.call_EvaluateLatency(transaction, blockTag, latency) + case SEND_METHOD_NAME: + const underlyingMethodName = args[0] + const params: Array = args.splice(1) + + return await this.send_EvaluateLatency(underlyingMethodName, params, latency) + default: + return await (this as any)[`${methodName}_EvaluateLatency`](...args) + } } catch (error: any) { this.log.error({ error }, `Encounter error for shadow evaluate latency call: ${JSON.stringify(error)}`) // Swallow the error. @@ -264,6 +277,7 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { callType: CallType, fnName: string, fn: (...args: any[]) => Promise, + latency?: number, ...args: any[] ): Promise { this.log.debug( @@ -284,6 +298,20 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { const result = await fn(...args) perf.latencyInMs = Date.now() - perf.startTimestampInMs + // The provider latency we evaluate against should always be faster than the provider we are using in prod currently. + // If that's not the case, we need to log the RPC request payload to help debugging. + if (latency && perf.latencyInMs > latency) { + const evaluatedLatency = perf.latencyInMs + this.log.error( + { latency, evaluatedLatency }, + `Slower evaluated latency for provider ${ + this.providerName + }. SingleJsonRpcProvider: wrappedFunctionCall: callType: ${callType}, provider: ${ + this.url + }, fnName: ${fnName}, fn: ${fn}, args: ${JSON.stringify([...args])}` + ) + } + return result } catch (error: any) { perf.succeed = false @@ -346,7 +374,7 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { ///////////////////// Begin of override functions ///////////////////// override getBlockNumber(): Promise { - return this.wrappedFunctionCall(CallType.NORMAL, 'getBlockNumber', this._getBlockNumber.bind(this)) + return this.wrappedFunctionCall(CallType.NORMAL, 'getBlockNumber', this._getBlockNumber.bind(this), undefined) } override getBlockWithTransactions( @@ -356,20 +384,28 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { CallType.NORMAL, 'getBlockWithTransactions', super.getBlockWithTransactions.bind(this), + undefined, blockHashOrBlockTag ) } override getCode(addressOrName: string | Promise, blockTag?: BlockTag | Promise): Promise { - return this.wrappedFunctionCall(CallType.NORMAL, 'getCode', super.getCode.bind(this), addressOrName, blockTag) + return this.wrappedFunctionCall( + CallType.NORMAL, + 'getCode', + super.getCode.bind(this), + undefined, + addressOrName, + blockTag + ) } override getGasPrice(): Promise { - return this.wrappedFunctionCall(CallType.NORMAL, 'getGasPrice', super.getGasPrice.bind(this)) + return this.wrappedFunctionCall(CallType.NORMAL, 'getGasPrice', super.getGasPrice.bind(this), undefined) } override getLogs(filter: Filter): Promise> { - return this.wrappedFunctionCall(CallType.NORMAL, 'getLogs', super.getLogs.bind(this), filter) + return this.wrappedFunctionCall(CallType.NORMAL, 'getLogs', super.getLogs.bind(this), undefined, filter) } override getStorageAt( @@ -381,6 +417,7 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { CallType.NORMAL, 'getStorageAt', super.getStorageAt.bind(this), + undefined, addressOrName, position, blockTag @@ -388,7 +425,13 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { } override getTransaction(transactionHash: string | Promise): Promise { - return this.wrappedFunctionCall(CallType.NORMAL, 'getTransaction', super.getTransaction.bind(this), transactionHash) + return this.wrappedFunctionCall( + CallType.NORMAL, + 'getTransaction', + super.getTransaction.bind(this), + undefined, + transactionHash + ) } override getTransactionCount( @@ -399,6 +442,7 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { CallType.NORMAL, 'getTransactionCount', super.getTransactionCount.bind(this), + undefined, addressOrName, blockTag ) @@ -409,16 +453,23 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { CallType.NORMAL, 'getTransactionReceipt', super.getTransactionReceipt.bind(this), + undefined, transactionHash ) } override lookupAddress(address: string | Promise): Promise { - return this.wrappedFunctionCall(CallType.NORMAL, 'lookupAddress', super.lookupAddress.bind(this), address) + return this.wrappedFunctionCall( + CallType.NORMAL, + 'lookupAddress', + super.lookupAddress.bind(this), + undefined, + address + ) } override resolveName(name: string | Promise): Promise { - return this.wrappedFunctionCall(CallType.NORMAL, 'resolveName', super.resolveName.bind(this), name) + return this.wrappedFunctionCall(CallType.NORMAL, 'resolveName', super.resolveName.bind(this), undefined, name) } override sendTransaction(signedTransaction: string | Promise): Promise { @@ -426,6 +477,7 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { CallType.NORMAL, 'sendTransaction', super.sendTransaction.bind(this), + undefined, signedTransaction ) } @@ -439,6 +491,7 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { CallType.NORMAL, 'waitForTransaction', super.waitForTransaction.bind(this), + undefined, transactionHash, confirmations, timeout @@ -446,12 +499,12 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { } override call(transaction: Deferrable, blockTag?: BlockTag | Promise): Promise { - return this.wrappedFunctionCall(CallType.NORMAL, 'call', super.call.bind(this), transaction, blockTag) + return this.wrappedFunctionCall(CallType.NORMAL, 'call', super.call.bind(this), undefined, transaction, blockTag) } override send(method: string, params: Array): Promise { this.logSendMetrod(method) - return this.wrappedFunctionCall(CallType.NORMAL, 'send', super.send.bind(this), method, params) + return this.wrappedFunctionCall(CallType.NORMAL, 'send', super.send.bind(this), undefined, method, params) } ///////////////////// Begin of special functions ///////////////////// @@ -463,24 +516,37 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider { } private getBlockNumber_EvaluateHealthiness(): Promise { - return this.wrappedFunctionCall(CallType.HEALTH_CHECK, 'getBlockNumber', this._getBlockNumber.bind(this)) + return this.wrappedFunctionCall(CallType.HEALTH_CHECK, 'getBlockNumber', this._getBlockNumber.bind(this), undefined) } // @ts-ignore private getBlockNumber_EvaluateLatency(): Promise { - return this.wrappedFunctionCall(CallType.LATENCY_EVALUATION, 'getBlockNumber', this._getBlockNumber.bind(this)) + return this.wrappedFunctionCall( + CallType.LATENCY_EVALUATION, + 'getBlockNumber', + this._getBlockNumber.bind(this), + undefined + ) } // @ts-ignore private call_EvaluateLatency( transaction: Deferrable, - blockTag?: BlockTag | Promise + blockTag?: BlockTag | Promise, + latency?: number ): Promise { - return this.wrappedFunctionCall(CallType.LATENCY_EVALUATION, 'call', super.call.bind(this), transaction, blockTag) + return this.wrappedFunctionCall( + CallType.LATENCY_EVALUATION, + 'call', + super.call.bind(this), + latency, + transaction, + blockTag + ) } // @ts-ignore - private send_EvaluateLatency(method: string, params: Array): Promise { - return this.wrappedFunctionCall(CallType.LATENCY_EVALUATION, 'send', super.send.bind(this), method, params) + private send_EvaluateLatency(method: string, params: Array, latency?: number): Promise { + return this.wrappedFunctionCall(CallType.LATENCY_EVALUATION, 'send', super.send.bind(this), latency, method, params) } } diff --git a/lib/rpc/UniJsonRpcProvider.ts b/lib/rpc/UniJsonRpcProvider.ts index ff7e5add54..bbc8897efa 100644 --- a/lib/rpc/UniJsonRpcProvider.ts +++ b/lib/rpc/UniJsonRpcProvider.ts @@ -239,7 +239,7 @@ export class UniJsonRpcProvider extends StaticJsonRpcProvider { // Within each provider latency shadow evaluation, we should do block I/O, // because NodeJS runs in single thread, so it's important to make sure // we benchmark the latencies correctly based on the single-threaded sequential evaluation. - const evaluatedProviderResponse = await provider[`evaluateLatency`](methodName, ...args) + const evaluatedProviderResponse = await provider[`evaluateLatency`](latency, methodName, ...args) // below invocation does not make the call/send RPC return the correct data // both call and send will return "0x" for some reason // I have to change to above invocation to make call/send return geniun RPC response diff --git a/test/mocha/unit/rpc/UniJsonRpcProvider.test.ts b/test/mocha/unit/rpc/UniJsonRpcProvider.test.ts index 4d61316aff..c7d1bf085d 100644 --- a/test/mocha/unit/rpc/UniJsonRpcProvider.test.ts +++ b/test/mocha/unit/rpc/UniJsonRpcProvider.test.ts @@ -704,9 +704,9 @@ describe('UniJsonRpcProvider', () => { // Shadow evaluate call should be made expect(spy0.callCount).to.equal(0) expect(spy1.callCount).to.equal(1) - expect(spy1.getCalls()[0].firstArg).to.equal('getBlockNumber') + expect(spy1.getCalls()[0].lastArg).to.equal('getBlockNumber') expect(spy2.callCount).to.equal(1) - expect(spy2.getCalls()[0].firstArg).to.equal('getBlockNumber') + expect(spy2.getCalls()[0].lastArg).to.equal('getBlockNumber') expect(uniProvider['providers'][1]['lastLatencyEvaluationTimestampInMs']).equals(timestamp) expect(uniProvider['providers'][2]['lastLatencyEvaluationTimestampInMs']).equals(timestamp) @@ -746,9 +746,9 @@ describe('UniJsonRpcProvider', () => { // Shadow evaluate call should be made expect(spy0.callCount).to.equal(0) expect(spy1.callCount).to.equal(1) - expect(spy1.getCalls()[0].firstArg).to.equal('getBlockNumber') + expect(spy1.getCalls()[0].lastArg).to.equal('getBlockNumber') expect(spy2.callCount).to.equal(1) - expect(spy2.getCalls()[0].firstArg).to.equal('getBlockNumber') + expect(spy2.getCalls()[0].lastArg).to.equal('getBlockNumber') expect(uniProvider['providers'][1]['lastLatencyEvaluationTimestampInMs']).equals(timestamp) expect(uniProvider['providers'][2]['lastLatencyEvaluationTimestampInMs']).equals(timestamp) @@ -774,10 +774,10 @@ describe('UniJsonRpcProvider', () => { await uniProvider.getBlockNumber('sessionId') expect(spy1.callCount).to.equal(1) - expect(spy1.getCalls()[0].firstArg).to.equal('getBlockNumber') + expect(spy1.getCalls()[0].lastArg).to.equal('getBlockNumber') expect(uniProvider['providers'][1]['lastLatencyEvaluationTimestampInMs']).equals(timestamp + 16000) expect(spy2.callCount).to.equal(1) - expect(spy2.getCalls()[0].firstArg).to.equal('getBlockNumber') + expect(spy2.getCalls()[0].lastArg).to.equal('getBlockNumber') expect(uniProvider['providers'][2]['lastLatencyEvaluationTimestampInMs']).equals(timestamp + 16000) }) @@ -822,9 +822,9 @@ describe('UniJsonRpcProvider', () => { expect(spy0.callCount).to.equal(0) expect(spy1.callCount).to.equal(5) - expect(spy1.getCalls()[0].firstArg).to.equal('getBlockNumber') + expect(spy1.getCalls()[0].lastArg).to.equal('getBlockNumber') expect(spy2.callCount).to.equal(5) - expect(spy2.getCalls()[0].firstArg).to.equal('getBlockNumber') + expect(spy2.getCalls()[0].lastArg).to.equal('getBlockNumber') expect(uniProvider['providers'][1]['lastLatencyEvaluationTimestampInMs']).equals(timestamp) expect(uniProvider['providers'][2]['lastLatencyEvaluationTimestampInMs']).equals(timestamp) @@ -946,9 +946,9 @@ describe('UniJsonRpcProvider', () => { // 0.4 < 0.5, Shadow evaluate call should be made expect(spy0.callCount).to.equal(0) expect(spy1.callCount).to.equal(1) - expect(spy1.getCalls()[0].firstArg).to.equal('getBlockNumber') + expect(spy1.getCalls()[0].lastArg).to.equal('getBlockNumber') expect(spy2.callCount).to.equal(1) - expect(spy2.getCalls()[0].firstArg).to.equal('getBlockNumber') + expect(spy2.getCalls()[0].lastArg).to.equal('getBlockNumber') }) it('Test use of healthCheckSampleProb', async () => {