Merge pull request #21 from kaleido-io/rpc-trace

Reconcile how we log RPC calls
hyperledger · Aug 29, 2022 · 0dca0a9 · 0dca0a9
2 parents 2c04aa8 + 02e9231
commit 0dca0a9
Show file tree

Hide file tree

Showing 5 changed files with 109 additions and 11 deletions.
diff --git 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
@@ -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
@@ -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"
+        }
+      ]
+    }
+  ]
diff --git 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
@@ -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)