From 02e92315ddd94508c671b48a0ef1ce4de0329433 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Mon, 29 Aug 2022 15:14:55 -0400 Subject: [PATCH] Reoncile how we log RPC calls Signed-off-by: Peter Broadhurst --- .vscode/settings.json | 2 + internal/signermsgs/en_error_messges.go | 2 +- pkg/abi/ethers.interface.sample.json | 87 +++++++++++++++++++++++++ pkg/rpcbackend/backend.go | 26 +++++--- pkg/rpcbackend/backend_test.go | 3 + 5 files changed, 109 insertions(+), 11 deletions(-) create mode 100644 pkg/abi/ethers.interface.sample.json diff --git a/.vscode/settings.json b/.vscode/settings.json index b4e38eac..d695c3a9 100644 --- a/.vscode/settings.json +++ b/.vscode/settings.json @@ -25,7 +25,9 @@ "Keccak", "keypair", "keystorev", + "logrus", "pluggable", + "proxying", "resty", "rpcbackendmocks", "secp", diff --git a/internal/signermsgs/en_error_messges.go b/internal/signermsgs/en_error_messges.go index 456e86bc..07ab7d6f 100644 --- a/internal/signermsgs/en_error_messges.go +++ b/internal/signermsgs/en_error_messges.go @@ -29,7 +29,7 @@ var ffe = func(key, translation string, statusHint ...int) i18n.ErrorMessageKey var ( MsgInvalidOutputType = ffe("FF22010", "Invalid output type: %s") MsgInvalidParam = ffe("FF22011", "Invalid parameter at position %d for method %s: %s") - MsgRPCRequestFailed = ffe("FF22012", "Backend RPC request failed: %s") + MsgRPCRequestFailed = ffe("FF22012", "Backend RPC request failed") MsgReadDirFile = ffe("FF22013", "Directory listing failed") MsgWalletNotAvailable = ffe("FF22014", "Wallet for address '%s' not available") MsgWalletFailed = ffe("FF22015", "Wallet for address '%s' could not be initialized") diff --git a/pkg/abi/ethers.interface.sample.json b/pkg/abi/ethers.interface.sample.json new file mode 100644 index 00000000..73c221b7 --- /dev/null +++ b/pkg/abi/ethers.interface.sample.json @@ -0,0 +1,87 @@ +[ + { + "type": "constructor", + "payable": false, + "inputs": [ + { + "type": "uint256", + "name": "initVal" + } + ] + }, + { + "type": "event", + "anonymous": false, + "name": "Changed", + "inputs": [ + { + "type": "uint256", + "name": "data", + "indexed": false + } + ] + }, + { + "type": "function", + "name": "get", + "constant": true, + "stateMutability": "view", + "payable": false, + "gas": 29000000, + "inputs": [], + "outputs": [ + { + "type": "uint256", + "name": "retVal" + } + ] + }, + { + "type": "function", + "name": "query", + "constant": true, + "stateMutability": "view", + "payable": false, + "gas": 29000000, + "inputs": [], + "outputs": [ + { + "type": "uint256", + "name": "retVal" + } + ] + }, + { + "type": "function", + "name": "set", + "constant": false, + "payable": false, + "gas": 29000000, + "inputs": [ + { + "type": "uint256", + "name": "x" + } + ], + "outputs": [ + { + "type": "uint256", + "name": "value" + } + ] + }, + { + "type": "function", + "name": "storedData", + "constant": true, + "stateMutability": "view", + "payable": false, + "gas": 29000000, + "inputs": [], + "outputs": [ + { + "type": "uint256" + } + ] + } + ] \ No newline at end of file diff --git a/pkg/rpcbackend/backend.go b/pkg/rpcbackend/backend.go index 31b60543..2c51880b 100644 --- a/pkg/rpcbackend/backend.go +++ b/pkg/rpcbackend/backend.go @@ -83,9 +83,10 @@ func (r *RPCResponse) Message() string { return "" } -func (rc *RPCClient) allocateRequestID(req *RPCRequest) { - reqID := atomic.AddInt64(&rc.requestCounter, 1) - req.ID = fftypes.JSONAnyPtr(fmt.Sprintf(`"%.9d"`, reqID)) +func (rc *RPCClient) allocateRequestID(req *RPCRequest) string { + reqID := fmt.Sprintf(`%.9d`, atomic.AddInt64(&rc.requestCounter, 1)) + req.ID = fftypes.JSONAnyPtr(`"` + reqID + `"`) + return reqID } func (rc *RPCClient) CallRPC(ctx context.Context, result interface{}, method string, params ...interface{}) error { @@ -119,13 +120,18 @@ func (rc *RPCClient) SyncRequest(ctx context.Context, rpcReq *RPCRequest) (rpcRe // multiple concurrent clients on our front-end that might use clashing IDs. var beReq = *rpcReq beReq.JSONRpc = "2.0" - rc.allocateRequestID(&beReq) + rpcTraceID := rc.allocateRequestID(&beReq) + if rpcReq.ID != nil { + // We're proxying a request with front-end RPC ID - log that as well + rpcTraceID = fmt.Sprintf("%s->%s", rpcReq.ID, rpcTraceID) + } + rpcRes = new(RPCResponse) - log.L(ctx).Debugf("RPC:%s:%s --> %s", rpcReq.ID, rpcReq.ID, rpcReq.Method) + log.L(ctx).Debugf("RPC[%s] --> %s", rpcTraceID, rpcReq.Method) if logrus.IsLevelEnabled(logrus.TraceLevel) { jsonInput, _ := json.Marshal(rpcReq) - log.L(ctx).Tracef("RPC:%s:%s INPUT: %s", rpcReq.ID, rpcReq.ID, jsonInput) + log.L(ctx).Tracef("RPC[%s] INPUT: %s", rpcTraceID, jsonInput) } res, err := rc.client.R(). SetContext(ctx). @@ -138,21 +144,21 @@ func (rc *RPCClient) SyncRequest(ctx context.Context, rpcReq *RPCRequest) (rpcRe rpcRes.ID = rpcReq.ID if err != nil { err := i18n.NewError(ctx, signermsgs.MsgRPCRequestFailed) - log.L(ctx).Errorf("RPC[%d] <-- ERROR: %s", rpcReq.ID, err) + log.L(ctx).Errorf("RPC[%s] <-- ERROR: %s", rpcTraceID, err) rpcRes = RPCErrorResponse(err, rpcReq.ID, RPCCodeInternalError) return rpcRes, err } if logrus.IsLevelEnabled(logrus.TraceLevel) { jsonOutput, _ := json.Marshal(rpcRes) - log.L(ctx).Tracef("RPC:%s:%s OUTPUT: %s", rpcReq.ID, rpcReq.ID, jsonOutput) + log.L(ctx).Tracef("RPC[%s] OUTPUT: %s", rpcTraceID, jsonOutput) } // JSON/RPC allows errors to be returned with a 200 status code, as well as other status codes if res.IsError() || rpcRes.Error != nil && rpcRes.Error.Code != 0 { - log.L(ctx).Errorf("RPC[%d] <-- [%d]: %s", rpcReq.ID, res.StatusCode(), rpcRes.Message()) + log.L(ctx).Errorf("RPC[%s] <-- [%d]: %s", rpcTraceID, res.StatusCode(), rpcRes.Message()) err := fmt.Errorf(rpcRes.Message()) return rpcRes, err } - log.L(ctx).Infof("RPC:%s:%s <-- [%d] OK", beReq.ID, rpcReq.ID, res.StatusCode()) + log.L(ctx).Infof("RPC[%s] <-- [%d] OK", rpcTraceID, res.StatusCode()) if rpcRes.Result == nil { // We don't want a result for errors, but a null success response needs to go in there rpcRes.Result = fftypes.JSONAnyPtr(fftypes.NullString) diff --git a/pkg/rpcbackend/backend_test.go b/pkg/rpcbackend/backend_test.go index 3a10e713..3073eaba 100644 --- a/pkg/rpcbackend/backend_test.go +++ b/pkg/rpcbackend/backend_test.go @@ -29,6 +29,7 @@ import ( "github.com/hyperledger/firefly-common/pkg/fftypes" "github.com/hyperledger/firefly-signer/internal/signerconfig" "github.com/hyperledger/firefly-signer/pkg/ethtypes" + "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" ) @@ -131,6 +132,8 @@ func TestSyncRequestOK(t *testing.T) { func TestSyncRPCCallOK(t *testing.T) { + logrus.SetLevel(logrus.TraceLevel) + ctx, rb, done := newTestServer(t, func(rpcReq *RPCRequest) (status int, rpcRes *RPCResponse) { assert.Equal(t, "2.0", rpcReq.JSONRpc) assert.Equal(t, "eth_getTransactionCount", rpcReq.Method)