From 95004cf4ceb312072a854cc3ba6e7e9080cf6201 Mon Sep 17 00:00:00 2001 From: Larry Ruane Date: Mon, 12 Aug 2024 17:00:55 -0600 Subject: [PATCH] Add debug logging to gRPC entrypoints This additional logging may help with debugging lightwalletd clients as it may isolate the problem to the client or server (lightwalletd) side. To see entrypoint logging, you must start lightwalletd with the option --log-level 5 (which is "debug"; the default is 4, which is "info")). This option shouldn't be used in normal operation, because clients could flood the log, causing crashes due to running out of disk space. Only use this when actually debugging or testing. For most gRPCs, also log return values if the log-level is 6 ("trace"). Return value logging isn't done if there is an error (it's assumed that the client will log something) or if the output might be very large (we don't want to overrun the log file). Enabling trace (--log-level 6) enables everything below that level, so entry logging is enabled as well. --- frontend/service.go | 62 +++++++++++++++++++++++++++++++++++++-------- 1 file changed, 51 insertions(+), 11 deletions(-) diff --git a/frontend/service.go b/frontend/service.go index 78adad3d..612eb0f9 100644 --- a/frontend/service.go +++ b/frontend/service.go @@ -59,6 +59,7 @@ func checkTaddress(taddr string) error { // GetLatestBlock returns the height and hash of the best chain, according to zcashd. func (s *lwdStreamer) GetLatestBlock(ctx context.Context, placeholder *walletrpc.ChainSpec) (*walletrpc.BlockID, error) { + common.Log.Debugf("gRPC GetLatestBlock(%+v)\n", placeholder) // Lock to ensure we return consistent height and hash s.mutex.Lock() defer s.mutex.Unlock() @@ -70,13 +71,16 @@ func (s *lwdStreamer) GetLatestBlock(ctx context.Context, placeholder *walletrpc if err != nil { return nil, err } - return &walletrpc.BlockID{Height: uint64(blockChainInfo.Blocks), Hash: []byte(bestBlockHash)}, nil + r := &walletrpc.BlockID{Height: uint64(blockChainInfo.Blocks), Hash: []byte(bestBlockHash)} + common.Log.Tracef(" return: %+v\n", r) + return r, nil } // GetTaddressTxids is a streaming RPC that returns transactions that have // the given transparent address (taddr) as either an input or output. // NB, this method is misnamed, it does not return txids. func (s *lwdStreamer) GetTaddressTxids(addressBlockFilter *walletrpc.TransparentAddressBlockFilter, resp walletrpc.CompactTxStreamer_GetTaddressTxidsServer) error { + common.Log.Debugf("gRPC GetTaddressTxids(%+v)\n", addressBlockFilter) if err := checkTaddress(addressBlockFilter.Address); err != nil { return err } @@ -135,6 +139,7 @@ func (s *lwdStreamer) GetTaddressTxids(addressBlockFilter *walletrpc.Transparent // GetBlock returns the compact block at the requested height. Requesting a // block by hash is not yet supported. func (s *lwdStreamer) GetBlock(ctx context.Context, id *walletrpc.BlockID) (*walletrpc.CompactBlock, error) { + common.Log.Debugf("gRPC GetBlock(%+v)\n", id) if id.Height == 0 && id.Hash == nil { return nil, errors.New("request for unspecified identifier") } @@ -150,12 +155,14 @@ func (s *lwdStreamer) GetBlock(ctx context.Context, id *walletrpc.BlockID) (*wal if err != nil { return nil, err } + common.Log.Tracef(" return: %+v\n", cBlock) return cBlock, err } // GetBlockNullifiers is the same as GetBlock except that it returns the compact block // with actions containing only the nullifiers (a subset of the full compact block). func (s *lwdStreamer) GetBlockNullifiers(ctx context.Context, id *walletrpc.BlockID) (*walletrpc.CompactBlock, error) { + common.Log.Debugf("gRPC GetBlockNullifiers(%+v)\n", id) if id.Height == 0 && id.Hash == nil { return nil, errors.New("request for unspecified identifier") } @@ -180,6 +187,7 @@ func (s *lwdStreamer) GetBlockNullifiers(ctx context.Context, id *walletrpc.Bloc // these are not needed (we prefer to save bandwidth) cBlock.ChainMetadata.SaplingCommitmentTreeSize = 0 cBlock.ChainMetadata.OrchardCommitmentTreeSize = 0 + common.Log.Tracef(" return: %+v\n", cBlock) return cBlock, err } @@ -187,6 +195,7 @@ func (s *lwdStreamer) GetBlockNullifiers(ctx context.Context, id *walletrpc.Bloc // (as also returned by GetBlock) from the block height 'start' to height // 'end' inclusively. func (s *lwdStreamer) GetBlockRange(span *walletrpc.BlockRange, resp walletrpc.CompactTxStreamer_GetBlockRangeServer) error { + common.Log.Debugf("gRPC GetBlockRange(%+v)\n", span) blockChan := make(chan *walletrpc.CompactBlock) if span.Start == nil || span.End == nil { return errors.New("must specify start and end heights") @@ -211,6 +220,7 @@ func (s *lwdStreamer) GetBlockRange(span *walletrpc.BlockRange, resp walletrpc.C // GetBlockRangeNullifiers is the same as GetBlockRange except that only // the actions contain only nullifiers (a subset of the full compact block). func (s *lwdStreamer) GetBlockRangeNullifiers(span *walletrpc.BlockRange, resp walletrpc.CompactTxStreamer_GetBlockRangeNullifiersServer) error { + common.Log.Debugf("gRPC GetBlockRangeNullifiers(%+v)\n", span) blockChan := make(chan *walletrpc.CompactBlock) if span.Start == nil || span.End == nil { return errors.New("must specify start and end heights") @@ -256,10 +266,13 @@ func (s *lwdStreamer) GetTreeState(ctx context.Context, id *walletrpc.BlockID) ( if err != nil { return nil, err } + common.Log.Debugf("gRPC GetTreeState(height=%+v)\n", id.Height) params[0] = heightJSON } else { // id.Hash is big-endian, keep in big-endian for the rpc - hashJSON, err := json.Marshal(hex.EncodeToString(id.Hash)) + hash := hex.EncodeToString(id.Hash) + common.Log.Debugf("gRPC GetTreeState(hash=%+v)\n", hash) + hashJSON, err := json.Marshal(hash) if err != nil { return nil, err } @@ -290,28 +303,36 @@ func (s *lwdStreamer) GetTreeState(ctx context.Context, id *walletrpc.BlockID) ( if gettreestateReply.Sapling.Commitments.FinalState == "" { return nil, errors.New(common.NodeName + " did not return treestate") } - return &walletrpc.TreeState{ + r := &walletrpc.TreeState{ Network: s.chainName, Height: uint64(gettreestateReply.Height), Hash: gettreestateReply.Hash, Time: gettreestateReply.Time, SaplingTree: gettreestateReply.Sapling.Commitments.FinalState, OrchardTree: gettreestateReply.Orchard.Commitments.FinalState, - }, nil + } + common.Log.Tracef(" return: %+v\n", r) + return r, nil } func (s *lwdStreamer) GetLatestTreeState(ctx context.Context, in *walletrpc.Empty) (*walletrpc.TreeState, error) { + common.Log.Debugf("gRPC GetLatestTreeState()\n") blockChainInfo, err := common.GetBlockChainInfo() if err != nil { return nil, err } latestHeight := blockChainInfo.Blocks - return s.GetTreeState(ctx, &walletrpc.BlockID{Height: uint64(latestHeight)}) + r, err := s.GetTreeState(ctx, &walletrpc.BlockID{Height: uint64(latestHeight)}) + if err == nil { + common.Log.Tracef(" return: %+v\n", r) + } + return r, err } // GetTransaction returns the raw transaction bytes that are returned // by the zcashd 'getrawtransaction' RPC. func (s *lwdStreamer) GetTransaction(ctx context.Context, txf *walletrpc.TxFilter) (*walletrpc.RawTransaction, error) { + common.Log.Debugf("gRPC GetTransaction(%+v)\n", txf) if txf.Hash != nil { if len(txf.Hash) != 32 { return nil, errors.New("transaction ID has invalid length") @@ -340,10 +361,12 @@ func (s *lwdStreamer) GetTransaction(ctx context.Context, txf *walletrpc.TxFilte if err != nil { return nil, err } - return &walletrpc.RawTransaction{ + r := &walletrpc.RawTransaction{ Data: txBytes, Height: uint64(txinfo.Height), - }, nil + } + common.Log.Tracef(" return: %+v\n", r) + return r, nil } if txf.Block != nil && txf.Block.Hash != nil { @@ -360,6 +383,7 @@ func (s *lwdStreamer) GetLightdInfo(ctx context.Context, in *walletrpc.Empty) (* // SendTransaction forwards raw transaction bytes to a zcashd instance over JSON-RPC func (s *lwdStreamer) SendTransaction(ctx context.Context, rawtx *walletrpc.RawTransaction) (*walletrpc.SendResponse, error) { + common.Log.Debugf("gRPC SendTransaction(%+v)\n", rawtx) // sendrawtransaction "hexstring" ( allowhighfees ) // // Submits raw transaction (binary) to local node and network. @@ -404,10 +428,12 @@ func (s *lwdStreamer) SendTransaction(ctx context.Context, rawtx *walletrpc.RawT // TODO these are called Error but they aren't at the moment. // A success will return code 0 and message txhash. - return &walletrpc.SendResponse{ + r := &walletrpc.SendResponse{ ErrorCode: int32(errCode), ErrorMessage: errMsg, - }, nil + } + common.Log.Tracef(" return: %+v\n", r) + return r, nil } func getTaddressBalanceZcashdRpc(addressList []string) (*walletrpc.Balance, error) { @@ -440,11 +466,17 @@ func getTaddressBalanceZcashdRpc(addressList []string) (*walletrpc.Balance, erro // GetTaddressBalance returns the total balance for a list of taddrs func (s *lwdStreamer) GetTaddressBalance(ctx context.Context, addresses *walletrpc.AddressList) (*walletrpc.Balance, error) { - return getTaddressBalanceZcashdRpc(addresses.Addresses) + common.Log.Debugf("gRPC GetTaddressBalance(%+v)\n", addresses) + r, err := getTaddressBalanceZcashdRpc(addresses.Addresses) + if err == nil { + common.Log.Tracef(" return: %+v\n", r) + } + return r, err } // GetTaddressBalanceStream returns the total balance for a list of taddrs func (s *lwdStreamer) GetTaddressBalanceStream(addresses walletrpc.CompactTxStreamer_GetTaddressBalanceStreamServer) error { + common.Log.Debugf("gRPC GetTaddressBalanceStream(%+v)\n", addresses) addressList := make([]string, 0) for { addr, err := addresses.Recv() @@ -461,10 +493,12 @@ func (s *lwdStreamer) GetTaddressBalanceStream(addresses walletrpc.CompactTxStre return err } addresses.SendAndClose(balance) + common.Log.Tracef(" return: %+v\n", balance) return nil } func (s *lwdStreamer) GetMempoolStream(_empty *walletrpc.Empty, resp walletrpc.CompactTxStreamer_GetMempoolStreamServer) error { + common.Log.Debugf("gRPC GetMempoolStream()\n") err := common.GetMempool(func(tx *walletrpc.RawTransaction) error { return resp.Send(tx) }) @@ -479,6 +513,7 @@ var mempoolList []string var lastMempool time.Time func (s *lwdStreamer) GetMempoolTx(exclude *walletrpc.Exclude, resp walletrpc.CompactTxStreamer_GetMempoolTxServer) error { + common.Log.Debugf("gRPC GetMempoolTx(%+v)\n", exclude) s.mutex.Lock() defer s.mutex.Unlock() @@ -667,6 +702,7 @@ func getAddressUtxos(arg *walletrpc.GetAddressUtxosArg, f func(*walletrpc.GetAdd } func (s *lwdStreamer) GetAddressUtxos(ctx context.Context, arg *walletrpc.GetAddressUtxosArg) (*walletrpc.GetAddressUtxosReplyList, error) { + common.Log.Debugf("gRPC GetAddressUtxos(%+v)\n", arg) addressUtxos := make([]*walletrpc.GetAddressUtxosReply, 0) err := getAddressUtxos(arg, func(utxo *walletrpc.GetAddressUtxosReply) error { addressUtxos = append(addressUtxos, utxo) @@ -675,10 +711,13 @@ func (s *lwdStreamer) GetAddressUtxos(ctx context.Context, arg *walletrpc.GetAdd if err != nil { return &walletrpc.GetAddressUtxosReplyList{}, err } - return &walletrpc.GetAddressUtxosReplyList{AddressUtxos: addressUtxos}, nil + r := &walletrpc.GetAddressUtxosReplyList{AddressUtxos: addressUtxos} + common.Log.Tracef(" return: %+v\n", r) + return r, nil } func (s *lwdStreamer) GetSubtreeRoots(arg *walletrpc.GetSubtreeRootsArg, resp walletrpc.CompactTxStreamer_GetSubtreeRootsServer) error { + common.Log.Debugf("gRPC GetSubtreeRoots(%+v)\n", arg) if common.DarksideEnabled { return common.DarksideGetSubtreeRoots(arg, resp) } @@ -742,6 +781,7 @@ func (s *lwdStreamer) GetSubtreeRoots(arg *walletrpc.GetSubtreeRootsArg, resp wa } func (s *lwdStreamer) GetAddressUtxosStream(arg *walletrpc.GetAddressUtxosArg, resp walletrpc.CompactTxStreamer_GetAddressUtxosStreamServer) error { + common.Log.Debugf("gRPC GetAddressUtxosStream(%+v)\n", arg) err := getAddressUtxos(arg, func(utxo *walletrpc.GetAddressUtxosReply) error { return resp.Send(utxo) })