Adding logger around electrum client calls

In case of electrum client timeouts/errors we wrap these calls to
measure the time it takes to complete it. In case of a sucessfull call
the elapsed time might be also benefitial for debugging purposes.

Author: dimpar

pkg/bitcoin/electrum/electrum.go

@@ -89,7 +89,9 @@ func (c *Connection) GetTransaction(
 			// as Esplora/Electrs doesn't support verbose transactions.
 			// See: https://github.com/Blockstream/electrs/pull/36
 			return client.GetRawTransaction(ctx, txID)
-		})
+		},
+		"GetRawTransaction",
+	)
 	if err != nil {
 		return nil, fmt.Errorf(
 			"failed to get raw transaction with ID [%s]: [%w]",
@@ -125,7 +127,9 @@ func (c *Connection) GetTransactionConfirmations(
 			// as Esplora/Electrs doesn't support verbose transactions.
 			// See: https://github.com/Blockstream/electrs/pull/36
 			return client.GetRawTransaction(ctx, txID)
-		})
+		},
+		"GetRawTransaction",
+	)
 	if err != nil {
 		return 0,
 			fmt.Errorf(
@@ -174,7 +178,9 @@ txOutLoop:
 				client *electrum.Client,
 			) ([]*electrum.GetMempoolResult, error) {
 				return client.GetHistory(ctx, reversedScriptHashString)
-			})
+			},
+			"GetHistory",
+		)
 		if err != nil {
 			// Don't return an error, but continue to the next TxOut entry.
 			txLogger.Errorf("failed to get history for script hash: [%v]", err)
@@ -239,7 +245,9 @@ func (c *Connection) BroadcastTransaction(
 		c,
 		func(ctx context.Context, client *electrum.Client) (string, error) {
 			return client.BroadcastTransaction(ctx, rawTx)
-		})
+		},
+		"BroadcastTransaction",
+	)
 	if err != nil {
 		return fmt.Errorf("failed to broadcast the transaction: [%w]", err)
 	}
@@ -261,7 +269,9 @@ func (c *Connection) GetLatestBlockHeight() (uint, error) {
 			}
 			tip := <-headersChan
 			return tip.Height, nil
-		})
+		},
+		"SubscribeHeaders",
+	)
 	if err != nil {
 		return 0, fmt.Errorf("failed to subscribe for headers: [%w]", err)
 	}
@@ -287,6 +297,7 @@ func (c *Connection) GetBlockHeader(
 		) (*electrum.GetBlockHeaderResult, error) {
 			return client.GetBlockHeader(ctx, uint32(blockHeight), 0)
 		},
+		"GetBlockHeader",
 	)
 	if err != nil {
 		return nil, fmt.Errorf("failed to get block header: [%w]", err)
@@ -321,6 +332,7 @@ func (c *Connection) GetTransactionMerkleProof(
 				uint32(blockHeight),
 			)
 		},
+		"GetMerkleProof",
 	)
 	if err != nil {
 		return nil, fmt.Errorf("failed to get merkle proof: [%w]", err)
@@ -430,7 +442,9 @@ func (c *Connection) getConfirmedScriptHistory(
 			client *electrum.Client,
 		) ([]*electrum.GetMempoolResult, error) {
 			return client.GetHistory(ctx, reversedScriptHashString)
-		})
+		},
+		"GetHistory",
+	)
 	if err != nil {
 		return nil, fmt.Errorf(
 			"failed to get history for script [0x%x]: [%v]",
@@ -561,7 +575,9 @@ func (c *Connection) getScriptMempool(
 			client *electrum.Client,
 		) ([]*electrum.GetMempoolResult, error) {
 			return client.GetMempool(ctx, reversedScriptHashString)
-		})
+		},
+		"GetMempool",
+	)
 	if err != nil {
 		return nil, fmt.Errorf(
 			"failed to get mempool for script [0x%x]: [%v]",
@@ -610,7 +626,9 @@ func (c *Connection) EstimateSatPerVByteFee(blocks uint32) (int64, error) {
 			//       since version 1.4.2 of the protocol. We need to replace it
 			//       somehow once it disappears from Electrum implementations.
 			return client.GetFee(ctx, blocks)
-		})
+		},
+		"GetFee",
+	)
 	if err != nil {
 		return 0, fmt.Errorf("failed to get fee: [%v]", err)
 	}
@@ -669,6 +687,7 @@ func (c *Connection) verifyServer() error {
 			}
 			return &Server{serverVersion, protocolVersion}, nil
 		},
+		"ServerVersion",
 	)
 	if err != nil {
 		return fmt.Errorf("failed to get server version: [%w]", err)
@@ -704,6 +723,7 @@ func (c *Connection) keepAlive() {
 				func(ctx context.Context, client *electrum.Client) (interface{}, error) {
 					return nil, client.Ping(ctx)
 				},
+				"Ping",
 			)
 			if err != nil {
 				logger.Errorf(
@@ -753,7 +773,11 @@ func connectWithRetry(
 func requestWithRetry[K interface{}](
 	c *Connection,
 	requestFn func(ctx context.Context, client *electrum.Client) (K, error),
+	requestName string,
 ) (K, error) {
+	startTime := time.Now()
+	logger.Infof("starting [%s] request to Electrum server", requestName)
+
 	var result K
 
 	err := wrappers.DoWithDefaultRetry(
@@ -779,6 +803,19 @@ func requestWithRetry[K interface{}](
 			return nil
 		})
 
+	solveRequestOutcome := func(err error) string {
+		if err != nil {
+			return fmt.Sprintf("error: [%v]", err)
+		}
+		return "success"
+	}
+
+	logger.Infof("[%s] request to Electrum server completed with [%s] after [%s]",
+		requestName,
+		solveRequestOutcome(err),
+		time.Since(startTime),
+	)
+
 	return result, err
 }