Skip to content

Commit 0dca0a9

Browse files
nguyernguyer
authored
Merge pull request #21 from kaleido-io/rpc-trace
Reconcile how we log RPC calls
2 parents 2c04aa8 + 02e9231 commit 0dca0a9

File tree

5 files changed

+109
-11
lines changed

5 files changed

+109
-11
lines changed

‎.vscode/settings.json‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,9 @@
2525
"Keccak",
2626
"keypair",
2727
"keystorev",
28+
"logrus",
2829
"pluggable",
30+
"proxying",
2931
"resty",
3032
"rpcbackendmocks",
3133
"secp",

‎internal/signermsgs/en_error_messges.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,7 @@ var ffe = func(key, translation string, statusHint ...int) i18n.ErrorMessageKey
2929
var (
3030
MsgInvalidOutputType = ffe("FF22010", "Invalid output type: %s")
3131
MsgInvalidParam = ffe("FF22011", "Invalid parameter at position %d for method %s: %s")
32-
MsgRPCRequestFailed = ffe("FF22012", "Backend RPC request failed: %s")
32+
MsgRPCRequestFailed = ffe("FF22012", "Backend RPC request failed")
3333
MsgReadDirFile = ffe("FF22013", "Directory listing failed")
3434
MsgWalletNotAvailable = ffe("FF22014", "Wallet for address '%s' not available")
3535
MsgWalletFailed = ffe("FF22015", "Wallet for address '%s' could not be initialized")

‎pkg/abi/ethers.interface.sample.json‎

Lines changed: 87 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,87 @@
1+
[
2+
{
3+
"type": "constructor",
4+
"payable": false,
5+
"inputs": [
6+
{
7+
"type": "uint256",
8+
"name": "initVal"
9+
}
10+
]
11+
},
12+
{
13+
"type": "event",
14+
"anonymous": false,
15+
"name": "Changed",
16+
"inputs": [
17+
{
18+
"type": "uint256",
19+
"name": "data",
20+
"indexed": false
21+
}
22+
]
23+
},
24+
{
25+
"type": "function",
26+
"name": "get",
27+
"constant": true,
28+
"stateMutability": "view",
29+
"payable": false,
30+
"gas": 29000000,
31+
"inputs": [],
32+
"outputs": [
33+
{
34+
"type": "uint256",
35+
"name": "retVal"
36+
}
37+
]
38+
},
39+
{
40+
"type": "function",
41+
"name": "query",
42+
"constant": true,
43+
"stateMutability": "view",
44+
"payable": false,
45+
"gas": 29000000,
46+
"inputs": [],
47+
"outputs": [
48+
{
49+
"type": "uint256",
50+
"name": "retVal"
51+
}
52+
]
53+
},
54+
{
55+
"type": "function",
56+
"name": "set",
57+
"constant": false,
58+
"payable": false,
59+
"gas": 29000000,
60+
"inputs": [
61+
{
62+
"type": "uint256",
63+
"name": "x"
64+
}
65+
],
66+
"outputs": [
67+
{
68+
"type": "uint256",
69+
"name": "value"
70+
}
71+
]
72+
},
73+
{
74+
"type": "function",
75+
"name": "storedData",
76+
"constant": true,
77+
"stateMutability": "view",
78+
"payable": false,
79+
"gas": 29000000,
80+
"inputs": [],
81+
"outputs": [
82+
{
83+
"type": "uint256"
84+
}
85+
]
86+
}
87+
]

‎pkg/rpcbackend/backend.go‎

Lines changed: 16 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -83,9 +83,10 @@ func (r *RPCResponse) Message() string {
8383
return ""
8484
}
8585

86-
func (rc *RPCClient) allocateRequestID(req *RPCRequest) {
87-
reqID := atomic.AddInt64(&rc.requestCounter, 1)
88-
req.ID = fftypes.JSONAnyPtr(fmt.Sprintf(`"%.9d"`, reqID))
86+
func (rc *RPCClient) allocateRequestID(req *RPCRequest) string {
87+
reqID := fmt.Sprintf(`%.9d`, atomic.AddInt64(&rc.requestCounter, 1))
88+
req.ID = fftypes.JSONAnyPtr(`"` + reqID + `"`)
89+
return reqID
8990
}
9091

9192
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
119120
// multiple concurrent clients on our front-end that might use clashing IDs.
120121
var beReq = *rpcReq
121122
beReq.JSONRpc = "2.0"
122-
rc.allocateRequestID(&beReq)
123+
rpcTraceID := rc.allocateRequestID(&beReq)
124+
if rpcReq.ID != nil {
125+
// We're proxying a request with front-end RPC ID - log that as well
126+
rpcTraceID = fmt.Sprintf("%s->%s", rpcReq.ID, rpcTraceID)
127+
}
128+
123129
rpcRes = new(RPCResponse)
124130

125-
log.L(ctx).Debugf("RPC:%s:%s --> %s", rpcReq.ID, rpcReq.ID, rpcReq.Method)
131+
log.L(ctx).Debugf("RPC[%s] --> %s", rpcTraceID, rpcReq.Method)
126132
if logrus.IsLevelEnabled(logrus.TraceLevel) {
127133
jsonInput, _ := json.Marshal(rpcReq)
128-
log.L(ctx).Tracef("RPC:%s:%s INPUT: %s", rpcReq.ID, rpcReq.ID, jsonInput)
134+
log.L(ctx).Tracef("RPC[%s] INPUT: %s", rpcTraceID, jsonInput)
129135
}
130136
res, err := rc.client.R().
131137
SetContext(ctx).
@@ -138,21 +144,21 @@ func (rc *RPCClient) SyncRequest(ctx context.Context, rpcReq *RPCRequest) (rpcRe
138144
rpcRes.ID = rpcReq.ID
139145
if err != nil {
140146
err := i18n.NewError(ctx, signermsgs.MsgRPCRequestFailed)
141-
log.L(ctx).Errorf("RPC[%d] <-- ERROR: %s", rpcReq.ID, err)
147+
log.L(ctx).Errorf("RPC[%s] <-- ERROR: %s", rpcTraceID, err)
142148
rpcRes = RPCErrorResponse(err, rpcReq.ID, RPCCodeInternalError)
143149
return rpcRes, err
144150
}
145151
if logrus.IsLevelEnabled(logrus.TraceLevel) {
146152
jsonOutput, _ := json.Marshal(rpcRes)
147-
log.L(ctx).Tracef("RPC:%s:%s OUTPUT: %s", rpcReq.ID, rpcReq.ID, jsonOutput)
153+
log.L(ctx).Tracef("RPC[%s] OUTPUT: %s", rpcTraceID, jsonOutput)
148154
}
149155
// JSON/RPC allows errors to be returned with a 200 status code, as well as other status codes
150156
if res.IsError() || rpcRes.Error != nil && rpcRes.Error.Code != 0 {
151-
log.L(ctx).Errorf("RPC[%d] <-- [%d]: %s", rpcReq.ID, res.StatusCode(), rpcRes.Message())
157+
log.L(ctx).Errorf("RPC[%s] <-- [%d]: %s", rpcTraceID, res.StatusCode(), rpcRes.Message())
152158
err := fmt.Errorf(rpcRes.Message())
153159
return rpcRes, err
154160
}
155-
log.L(ctx).Infof("RPC:%s:%s <-- [%d] OK", beReq.ID, rpcReq.ID, res.StatusCode())
161+
log.L(ctx).Infof("RPC[%s] <-- [%d] OK", rpcTraceID, res.StatusCode())
156162
if rpcRes.Result == nil {
157163
// We don't want a result for errors, but a null success response needs to go in there
158164
rpcRes.Result = fftypes.JSONAnyPtr(fftypes.NullString)

‎pkg/rpcbackend/backend_test.go‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@ import (
2929
"github.com/hyperledger/firefly-common/pkg/fftypes"
3030
"github.com/hyperledger/firefly-signer/internal/signerconfig"
3131
"github.com/hyperledger/firefly-signer/pkg/ethtypes"
32+
"github.com/sirupsen/logrus"
3233
"github.com/stretchr/testify/assert"
3334
)
3435

@@ -131,6 +132,8 @@ func TestSyncRequestOK(t *testing.T) {
131132

132133
func TestSyncRPCCallOK(t *testing.T) {
133134

135+
logrus.SetLevel(logrus.TraceLevel)
136+
134137
ctx, rb, done := newTestServer(t, func(rpcReq *RPCRequest) (status int, rpcRes *RPCResponse) {
135138
assert.Equal(t, "2.0", rpcReq.JSONRpc)
136139
assert.Equal(t, "eth_getTransactionCount", rpcReq.Method)

0 commit comments

Comments
 (0)