Merge pull request #7514 from yyforyongyu/rpc-verbose-log

itest+rpcserver: fix itest flake in `3rd_party_anchor_spend`

docs/release-notes/release-notes-0.16.1.md

@@ -20,6 +20,12 @@
 * [Add test vectors for
   option_zero_fee_htlc_tx](https://github.com/lightningnetwork/lnd/pull/7439)
 
+## RPC
+
+- A [debug log](https://github.com/lightningnetwork/lnd/pull/7514) has been
+  added to `lnrpc` so the node operator can know whether a certain request has
+  happened or not.
+
 # Contributors (Alphabetical Order)
 
 * Elle Mouton

itest/lnd_onchain_test.go

@@ -430,6 +430,15 @@ func testAnchorThirdPartySpend(ht *lntest.HarnessTest) {
 	commitTxn := ht.Miner.GetRawTransaction(forceCloseTxID)
 	ht.Miner.MineBlockWithTxes([]*btcutil.Tx{commitTxn})
 
+	// Assert that the channel is now in PendingForceClose.
+	//
+	// NOTE: We must do this check to make sure `lnd` node has updated its
+	// internal state regarding the closing transaction, otherwise the
+	// `SendCoins` below might fail since it involves a reserved value
+	// check, which requires a certain amount of coins to be reserved based
+	// on the number of anchor channels.
+	ht.AssertChannelPendingForceClose(alice, aliceChanPoint1)
+
 	// With the anchor output located, and the main commitment mined we'll
 	// instruct the wallet to send all coins in the wallet to a new address
 	// (to the miner), including unconfirmed change.

rpcperms/interceptor.go

@@ -772,6 +772,8 @@ func (r *InterceptorChain) rpcStateUnaryServerInterceptor() grpc.UnaryServerInte
 	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo,
 		handler grpc.UnaryHandler) (interface{}, error) {
 
+		r.rpcsLog.Debugf("[%v] requested", info.FullMethod)
+
 		if err := r.checkRPCState(info.Server); err != nil {
 			return nil, err
 		}
@@ -786,6 +788,8 @@ func (r *InterceptorChain) rpcStateStreamServerInterceptor() grpc.StreamServerIn
 	return func(srv interface{}, ss grpc.ServerStream,
 		info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
 
+		r.rpcsLog.Debugf("[%v] requested", info.FullMethod)
+
 		if err := r.checkRPCState(srv); err != nil {
 			return err
 		}

rpcserver.go

@@ -2941,8 +2941,6 @@ func (r *rpcServer) GetRecoveryInfo(ctx context.Context,
 func (r *rpcServer) ListPeers(ctx context.Context,
 	in *lnrpc.ListPeersRequest) (*lnrpc.ListPeersResponse, error) {
 
-	rpcsLog.Tracef("[listpeers] request")
-
 	serverPeers := r.server.Peers()
 	resp := &lnrpc.ListPeersResponse{
 		Peers: make([]*lnrpc.Peer, 0, len(serverPeers)),
@@ -3701,8 +3699,6 @@ func (r *rpcServer) PendingChannels(ctx context.Context,
 	in *lnrpc.PendingChannelsRequest) (
 	*lnrpc.PendingChannelsResponse, error) {
 
-	rpcsLog.Debugf("[pendingchannels]")
-
 	resp := &lnrpc.PendingChannelsResponse{}
 
 	// First, we find all the channels that will soon be opened.
@@ -6409,8 +6405,6 @@ func marshallTopologyChange(topChange *routing.TopologyChange) *lnrpc.GraphTopol
 func (r *rpcServer) ListPayments(ctx context.Context,
 	req *lnrpc.ListPaymentsRequest) (*lnrpc.ListPaymentsResponse, error) {
 
-	rpcsLog.Debugf("[ListPayments]")
-
 	// If both dates are set, we check that the start date is less than the
 	// end date, otherwise we'll get an empty result.
 	if req.CreationDateStart != 0 && req.CreationDateEnd != 0 {
@@ -6627,10 +6621,6 @@ const feeBase float64 = 1000000
 func (r *rpcServer) FeeReport(ctx context.Context,
 	_ *lnrpc.FeeReportRequest) (*lnrpc.FeeReportResponse, error) {
 
-	// TODO(roasbeef): use UnaryInterceptor to add automated logging
-
-	rpcsLog.Debugf("[feereport]")
-
 	channelGraph := r.server.graphDB
 	selfNode, err := channelGraph.SourceNode()
 	if err != nil {
@@ -6894,8 +6884,6 @@ func (r *rpcServer) ForwardingHistory(ctx context.Context,
 	req *lnrpc.ForwardingHistoryRequest) (*lnrpc.ForwardingHistoryResponse,
 	error) {
 
-	rpcsLog.Debugf("[forwardinghistory]")
-
 	// Before we perform the queries below, we'll instruct the switch to
 	// flush any pending events to disk. This ensure we get a complete
 	// snapshot at this particular time.
@@ -7426,8 +7414,6 @@ func (r *rpcServer) ChannelAcceptor(stream lnrpc.Lightning_ChannelAcceptorServer
 func (r *rpcServer) BakeMacaroon(ctx context.Context,
 	req *lnrpc.BakeMacaroonRequest) (*lnrpc.BakeMacaroonResponse, error) {
 
-	rpcsLog.Debugf("[bakemacaroon]")
-
 	// If the --no-macaroons flag is used to start lnd, the macaroon service
 	// is not initialized. Therefore we can't bake new macaroons.
 	if r.macService == nil {
@@ -7514,8 +7500,6 @@ func (r *rpcServer) ListMacaroonIDs(ctx context.Context,
 	req *lnrpc.ListMacaroonIDsRequest) (
 	*lnrpc.ListMacaroonIDsResponse, error) {
 
-	rpcsLog.Debugf("[listmacaroonids]")
-
 	// If the --no-macaroons flag is used to start lnd, the macaroon service
 	// is not initialized. Therefore we can't show any IDs.
 	if r.macService == nil {
@@ -7546,8 +7530,6 @@ func (r *rpcServer) DeleteMacaroonID(ctx context.Context,
 	req *lnrpc.DeleteMacaroonIDRequest) (
 	*lnrpc.DeleteMacaroonIDResponse, error) {
 
-	rpcsLog.Debugf("[deletemacaroonid]")
-
 	// If the --no-macaroons flag is used to start lnd, the macaroon service
 	// is not initialized. Therefore we can't delete any IDs.
 	if r.macService == nil {
@@ -7577,8 +7559,6 @@ func (r *rpcServer) ListPermissions(_ context.Context,
 	_ *lnrpc.ListPermissionsRequest) (*lnrpc.ListPermissionsResponse,
 	error) {
 
-	rpcsLog.Debugf("[listpermissions]")
-
 	permissionMap := make(map[string]*lnrpc.MacaroonPermissionList)
 	for uri, perms := range r.interceptorChain.Permissions() {
 		rpcPerms := make([]*lnrpc.MacaroonPermission, len(perms))