From e4795dbeb5ddc10b6f788e84a01f702bf21e3110 Mon Sep 17 00:00:00 2001 From: Dmitry Date: Wed, 13 Sep 2023 22:18:09 +0200 Subject: [PATCH 1/4] Removing a TODO comments because the issue was resolved --- pkg/bitcoin/electrum/electrum.go | 4 ---- 1 file changed, 4 deletions(-) diff --git a/pkg/bitcoin/electrum/electrum.go b/pkg/bitcoin/electrum/electrum.go index 06902af4de..73ee50b41f 100644 --- a/pkg/bitcoin/electrum/electrum.go +++ b/pkg/bitcoin/electrum/electrum.go @@ -21,10 +21,6 @@ import ( "github.com/keep-network/keep-core/pkg/internal/byteutils" ) -// TODO: Some problems with Electrum re-connect were detected while developing -// integration tests: https://github.com/keep-network/keep-core/issues/3586. -// Make sure the problem is resolved soon. - var ( supportedProtocolVersions = []string{"1.4"} logger = log.Logger("keep-electrum") From 678a2ff02e7587edeee856f844bf0c18cb1265f1 Mon Sep 17 00:00:00 2001 From: Dmitry Date: Thu, 14 Sep 2023 11:51:02 +0200 Subject: [PATCH 2/4] 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. --- pkg/bitcoin/electrum/electrum.go | 153 ++++++++++++++++++++++++++++--- 1 file changed, 142 insertions(+), 11 deletions(-) diff --git a/pkg/bitcoin/electrum/electrum.go b/pkg/bitcoin/electrum/electrum.go index 73ee50b41f..bc846161f6 100644 --- a/pkg/bitcoin/electrum/electrum.go +++ b/pkg/bitcoin/electrum/electrum.go @@ -82,6 +82,9 @@ func (c *Connection) GetTransaction( ) (*bitcoin.Transaction, error) { txID := transactionHash.Hex(bitcoin.ReversedByteOrder) + logger.Infof("starting [%s] call to Electrum server", "GetRawTransaction") + + startTime := time.Now() rawTransaction, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (string, error) { @@ -90,14 +93,21 @@ func (c *Connection) GetTransaction( // See: https://github.com/Blockstream/electrs/pull/36 return client.GetRawTransaction(ctx, txID) }) + elapsed := time.Since(startTime) if err != nil { return nil, fmt.Errorf( - "failed to get raw transaction with ID [%s]: [%w]", + "failed to get raw transaction with ID [%s] after [%s]: [%w]", txID, + elapsed, err, ) } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "GetRawTransaction", + elapsed, + ) + result, err := convertRawTransaction(rawTransaction) if err != nil { return nil, fmt.Errorf("failed to convert transaction: [%w]", err) @@ -118,6 +128,9 @@ func (c *Connection) GetTransactionConfirmations( zap.String("txID", txID), ) + logger.Infof("starting [%s] call to Electrum server", "GetRawTransaction") + + startTime := time.Now() rawTransaction, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (string, error) { @@ -126,15 +139,22 @@ func (c *Connection) GetTransactionConfirmations( // See: https://github.com/Blockstream/electrs/pull/36 return client.GetRawTransaction(ctx, txID) }) + elapsed := time.Since(startTime) if err != nil { return 0, fmt.Errorf( - "failed to get raw transaction with ID [%s]: [%w]", + "failed to get raw transaction with ID [%s] after [%s]: [%w]", txID, + elapsed, err, ) } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "GetRawTransaction", + elapsed, + ) + tx, err := decodeTransaction(rawTransaction) if err != nil { return 0, fmt.Errorf( @@ -167,6 +187,9 @@ txOutLoop: reversedScriptHash := byteutils.Reverse(scriptHash[:]) reversedScriptHashString := hex.EncodeToString(reversedScriptHash) + logger.Infof("starting [%s] call to Electrum server", "GetHistory") + + startTime := time.Now() scriptHashHistory, err := requestWithRetry( c, func( @@ -175,12 +198,21 @@ txOutLoop: ) ([]*electrum.GetMempoolResult, error) { return client.GetHistory(ctx, reversedScriptHashString) }) + elapsed := time.Since(startTime) 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) + txLogger.Errorf("failed to get history for script hash after [%s]: [%v]", + elapsed, + err, + ) continue txOutLoop } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "GetHistory", + elapsed, + ) + for _, transaction := range scriptHashHistory { if transaction.Hash == txID { txBlockHeight = transaction.Height @@ -233,16 +265,27 @@ func (c *Connection) BroadcastTransaction( ) rawTxLogger.Debugf("broadcasting transaction") + logger.Infof("starting [%s] call to Electrum server", "BroadcastTransaction") + var response string + startTime := time.Now() response, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (string, error) { return client.BroadcastTransaction(ctx, rawTx) }) + elapsed := time.Since(startTime) if err != nil { - return fmt.Errorf("failed to broadcast the transaction: [%w]", err) + return fmt.Errorf("failed to broadcast the transaction after [%s]: [%w]", + elapsed, + err, + ) } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "BroadcastTransaction", + elapsed, + ) rawTxLogger.Infof("transaction broadcast successful: [%s]", response) @@ -252,6 +295,9 @@ func (c *Connection) BroadcastTransaction( // GetLatestBlockHeight gets the height of the latest block (tip). If the // latest block was not determined, this function returns an error. func (c *Connection) GetLatestBlockHeight() (uint, error) { + logger.Infof("starting [%s] call to Electrum server", "SubscribeHeaders") + + startTime := time.Now() blockHeight, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (int32, error) { @@ -262,10 +308,19 @@ func (c *Connection) GetLatestBlockHeight() (uint, error) { tip := <-headersChan return tip.Height, nil }) + elapsed := time.Since(startTime) if err != nil { - return 0, fmt.Errorf("failed to subscribe for headers: [%w]", err) + return 0, fmt.Errorf("failed to subscribe for headers after [%s]: [%w]", + elapsed, + err, + ) } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "SubscribeHeaders", + elapsed, + ) + if blockHeight > 0 { return uint(blockHeight), nil } @@ -279,6 +334,10 @@ func (c *Connection) GetLatestBlockHeight() (uint, error) { func (c *Connection) GetBlockHeader( blockHeight uint, ) (*bitcoin.BlockHeader, error) { + + logger.Infof("starting [%s] call to Electrum server", "GetBlockHeader") + + startTime := time.Now() getBlockHeaderResult, err := requestWithRetry( c, func( @@ -288,10 +347,19 @@ func (c *Connection) GetBlockHeader( return client.GetBlockHeader(ctx, uint32(blockHeight), 0) }, ) + elapsed := time.Since(startTime) if err != nil { - return nil, fmt.Errorf("failed to get block header: [%w]", err) + return nil, fmt.Errorf("failed to get block header after [%s]: [%w]", + elapsed, + err, + ) } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "GetBlockHeader", + elapsed, + ) + blockHeader, err := convertBlockHeader(getBlockHeaderResult) if err != nil { return nil, fmt.Errorf("failed to convert block header: %w", err) @@ -309,6 +377,9 @@ func (c *Connection) GetTransactionMerkleProof( ) (*bitcoin.TransactionMerkleProof, error) { txID := transactionHash.Hex(bitcoin.ReversedByteOrder) + logger.Infof("starting [%s] call to Electrum server", "GetMerkleProof") + + startTime := time.Now() getMerkleProofResult, err := requestWithRetry( c, func( @@ -322,10 +393,19 @@ func (c *Connection) GetTransactionMerkleProof( ) }, ) + elapsed := time.Since(startTime) if err != nil { - return nil, fmt.Errorf("failed to get merkle proof: [%w]", err) + return nil, fmt.Errorf("failed to get merkle proof after [%s]: [%w]", + "GetMerkleProof", + err, + ) } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "GetMerkleProof", + elapsed, + ) + return convertMerkleProof(getMerkleProofResult), nil } @@ -423,6 +503,9 @@ func (c *Connection) getConfirmedScriptHistory( reversedScriptHash := byteutils.Reverse(scriptHash[:]) reversedScriptHashString := hex.EncodeToString(reversedScriptHash) + logger.Infof("starting [%s] call to Electrum server", "GetHistory") + + startTime := time.Now() items, err := requestWithRetry( c, func( @@ -431,14 +514,21 @@ func (c *Connection) getConfirmedScriptHistory( ) ([]*electrum.GetMempoolResult, error) { return client.GetHistory(ctx, reversedScriptHashString) }) + elapsed := time.Since(startTime) if err != nil { return nil, fmt.Errorf( - "failed to get history for script [0x%x]: [%v]", + "failed to get history for script [0x%x] after [%s]: [%v]", script, + elapsed, err, ) } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "GetHistory", + elapsed, + ) + // According to https://electrumx.readthedocs.io/en/latest/protocol-methods.html#blockchain-scripthash-get-history // unconfirmed items living in the mempool are appended at the end of the // returned list and their height value is either -1 or 0. That means @@ -554,6 +644,9 @@ func (c *Connection) getScriptMempool( reversedScriptHash := byteutils.Reverse(scriptHash[:]) reversedScriptHashString := hex.EncodeToString(reversedScriptHash) + logger.Infof("starting [%s] call to Electrum server", "GetMempool") + + startTime := time.Now() items, err := requestWithRetry( c, func( @@ -562,6 +655,7 @@ func (c *Connection) getScriptMempool( ) ([]*electrum.GetMempoolResult, error) { return client.GetMempool(ctx, reversedScriptHashString) }) + elapsed := time.Since(startTime) if err != nil { return nil, fmt.Errorf( "failed to get mempool for script [0x%x]: [%v]", @@ -570,6 +664,11 @@ func (c *Connection) getScriptMempool( ) } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "GetMempool", + elapsed, + ) + convertedItems := make([]*scriptMempoolItem, len(items)) for i, item := range items { txHash, err := bitcoin.NewHashFromString( @@ -597,6 +696,9 @@ func (c *Connection) getScriptMempool( // EstimateSatPerVByteFee returns the estimated sat/vbyte fee for a // transaction to be confirmed within the given number of blocks. func (c *Connection) EstimateSatPerVByteFee(blocks uint32) (int64, error) { + logger.Infof("starting [%s] call to Electrum server", "GetFee") + + startTime := time.Now() // According to Electrum protocol docs, the returned fee is BTC/KB. btcPerKbFee, err := requestWithRetry( c, @@ -611,10 +713,19 @@ func (c *Connection) EstimateSatPerVByteFee(blocks uint32) (int64, error) { // somehow once it disappears from Electrum implementations. return client.GetFee(ctx, blocks) }) + elapsed := time.Since(startTime) if err != nil { - return 0, fmt.Errorf("failed to get fee: [%v]", err) + return 0, fmt.Errorf("failed to get fee after [%s]: [%v]", + elapsed, + err, + ) } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "GetFee", + elapsed, + ) + // According to Electrum protocol docs, if the daemon does not have // enough information to make an estimate, the integer -1 is returned. if btcPerKbFee < 0 { @@ -659,7 +770,9 @@ func (c *Connection) verifyServer() error { version string protocol string } + logger.Infof("starting [%s] call to Electrum server", "ServerVersion") + startTime := time.Now() server, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (*Server, error) { @@ -670,10 +783,19 @@ func (c *Connection) verifyServer() error { return &Server{serverVersion, protocolVersion}, nil }, ) + elapsed := time.Since(startTime) if err != nil { - return fmt.Errorf("failed to get server version: [%w]", err) + return fmt.Errorf("failed to get server version after [%s]: [%w]", + elapsed, + err, + ) } + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "ServerVersion", + elapsed, + ) + logger.Infof( "connected to electrum server [version: [%s], protocol: [%s]]", server.version, @@ -699,21 +821,30 @@ func (c *Connection) keepAlive() { for { select { case <-ticker.C: + logger.Infof("starting [%s] call to Electrum server", "Ping") + + startTime := time.Now() _, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (interface{}, error) { return nil, client.Ping(ctx) }, ) + elapsed := time.Since(startTime) if err != nil { logger.Errorf( - "failed to ping the electrum server; "+ + "failed to ping the electrum server after [%s]; "+ "please verify health of the electrum server: [%v]", + elapsed, err, ) } else { // Adjust ticker starting at the time of the latest successful ping. ticker = time.NewTicker(c.config.KeepAliveInterval) + logger.Infof("successfully completed [%s] call to Electrum server after [%s]", + "Ping", + elapsed, + ) } case <-c.parentCtx.Done(): ticker.Stop() From d768be065f80d406adfe460a0db20140a3477492 Mon Sep 17 00:00:00 2001 From: Dmitry Date: Thu, 14 Sep 2023 12:51:53 +0200 Subject: [PATCH 3/4] Revert "Adding logger around electrum client calls" This reverts commit 678a2ff02e7587edeee856f844bf0c18cb1265f1. --- pkg/bitcoin/electrum/electrum.go | 153 +++---------------------------- 1 file changed, 11 insertions(+), 142 deletions(-) diff --git a/pkg/bitcoin/electrum/electrum.go b/pkg/bitcoin/electrum/electrum.go index bc846161f6..73ee50b41f 100644 --- a/pkg/bitcoin/electrum/electrum.go +++ b/pkg/bitcoin/electrum/electrum.go @@ -82,9 +82,6 @@ func (c *Connection) GetTransaction( ) (*bitcoin.Transaction, error) { txID := transactionHash.Hex(bitcoin.ReversedByteOrder) - logger.Infof("starting [%s] call to Electrum server", "GetRawTransaction") - - startTime := time.Now() rawTransaction, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (string, error) { @@ -93,21 +90,14 @@ func (c *Connection) GetTransaction( // See: https://github.com/Blockstream/electrs/pull/36 return client.GetRawTransaction(ctx, txID) }) - elapsed := time.Since(startTime) if err != nil { return nil, fmt.Errorf( - "failed to get raw transaction with ID [%s] after [%s]: [%w]", + "failed to get raw transaction with ID [%s]: [%w]", txID, - elapsed, err, ) } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "GetRawTransaction", - elapsed, - ) - result, err := convertRawTransaction(rawTransaction) if err != nil { return nil, fmt.Errorf("failed to convert transaction: [%w]", err) @@ -128,9 +118,6 @@ func (c *Connection) GetTransactionConfirmations( zap.String("txID", txID), ) - logger.Infof("starting [%s] call to Electrum server", "GetRawTransaction") - - startTime := time.Now() rawTransaction, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (string, error) { @@ -139,22 +126,15 @@ func (c *Connection) GetTransactionConfirmations( // See: https://github.com/Blockstream/electrs/pull/36 return client.GetRawTransaction(ctx, txID) }) - elapsed := time.Since(startTime) if err != nil { return 0, fmt.Errorf( - "failed to get raw transaction with ID [%s] after [%s]: [%w]", + "failed to get raw transaction with ID [%s]: [%w]", txID, - elapsed, err, ) } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "GetRawTransaction", - elapsed, - ) - tx, err := decodeTransaction(rawTransaction) if err != nil { return 0, fmt.Errorf( @@ -187,9 +167,6 @@ txOutLoop: reversedScriptHash := byteutils.Reverse(scriptHash[:]) reversedScriptHashString := hex.EncodeToString(reversedScriptHash) - logger.Infof("starting [%s] call to Electrum server", "GetHistory") - - startTime := time.Now() scriptHashHistory, err := requestWithRetry( c, func( @@ -198,21 +175,12 @@ txOutLoop: ) ([]*electrum.GetMempoolResult, error) { return client.GetHistory(ctx, reversedScriptHashString) }) - elapsed := time.Since(startTime) if err != nil { // Don't return an error, but continue to the next TxOut entry. - txLogger.Errorf("failed to get history for script hash after [%s]: [%v]", - elapsed, - err, - ) + txLogger.Errorf("failed to get history for script hash: [%v]", err) continue txOutLoop } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "GetHistory", - elapsed, - ) - for _, transaction := range scriptHashHistory { if transaction.Hash == txID { txBlockHeight = transaction.Height @@ -265,27 +233,16 @@ func (c *Connection) BroadcastTransaction( ) rawTxLogger.Debugf("broadcasting transaction") - logger.Infof("starting [%s] call to Electrum server", "BroadcastTransaction") - var response string - startTime := time.Now() response, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (string, error) { return client.BroadcastTransaction(ctx, rawTx) }) - elapsed := time.Since(startTime) if err != nil { - return fmt.Errorf("failed to broadcast the transaction after [%s]: [%w]", - elapsed, - err, - ) + return fmt.Errorf("failed to broadcast the transaction: [%w]", err) } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "BroadcastTransaction", - elapsed, - ) rawTxLogger.Infof("transaction broadcast successful: [%s]", response) @@ -295,9 +252,6 @@ func (c *Connection) BroadcastTransaction( // GetLatestBlockHeight gets the height of the latest block (tip). If the // latest block was not determined, this function returns an error. func (c *Connection) GetLatestBlockHeight() (uint, error) { - logger.Infof("starting [%s] call to Electrum server", "SubscribeHeaders") - - startTime := time.Now() blockHeight, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (int32, error) { @@ -308,19 +262,10 @@ func (c *Connection) GetLatestBlockHeight() (uint, error) { tip := <-headersChan return tip.Height, nil }) - elapsed := time.Since(startTime) if err != nil { - return 0, fmt.Errorf("failed to subscribe for headers after [%s]: [%w]", - elapsed, - err, - ) + return 0, fmt.Errorf("failed to subscribe for headers: [%w]", err) } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "SubscribeHeaders", - elapsed, - ) - if blockHeight > 0 { return uint(blockHeight), nil } @@ -334,10 +279,6 @@ func (c *Connection) GetLatestBlockHeight() (uint, error) { func (c *Connection) GetBlockHeader( blockHeight uint, ) (*bitcoin.BlockHeader, error) { - - logger.Infof("starting [%s] call to Electrum server", "GetBlockHeader") - - startTime := time.Now() getBlockHeaderResult, err := requestWithRetry( c, func( @@ -347,19 +288,10 @@ func (c *Connection) GetBlockHeader( return client.GetBlockHeader(ctx, uint32(blockHeight), 0) }, ) - elapsed := time.Since(startTime) if err != nil { - return nil, fmt.Errorf("failed to get block header after [%s]: [%w]", - elapsed, - err, - ) + return nil, fmt.Errorf("failed to get block header: [%w]", err) } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "GetBlockHeader", - elapsed, - ) - blockHeader, err := convertBlockHeader(getBlockHeaderResult) if err != nil { return nil, fmt.Errorf("failed to convert block header: %w", err) @@ -377,9 +309,6 @@ func (c *Connection) GetTransactionMerkleProof( ) (*bitcoin.TransactionMerkleProof, error) { txID := transactionHash.Hex(bitcoin.ReversedByteOrder) - logger.Infof("starting [%s] call to Electrum server", "GetMerkleProof") - - startTime := time.Now() getMerkleProofResult, err := requestWithRetry( c, func( @@ -393,19 +322,10 @@ func (c *Connection) GetTransactionMerkleProof( ) }, ) - elapsed := time.Since(startTime) if err != nil { - return nil, fmt.Errorf("failed to get merkle proof after [%s]: [%w]", - "GetMerkleProof", - err, - ) + return nil, fmt.Errorf("failed to get merkle proof: [%w]", err) } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "GetMerkleProof", - elapsed, - ) - return convertMerkleProof(getMerkleProofResult), nil } @@ -503,9 +423,6 @@ func (c *Connection) getConfirmedScriptHistory( reversedScriptHash := byteutils.Reverse(scriptHash[:]) reversedScriptHashString := hex.EncodeToString(reversedScriptHash) - logger.Infof("starting [%s] call to Electrum server", "GetHistory") - - startTime := time.Now() items, err := requestWithRetry( c, func( @@ -514,21 +431,14 @@ func (c *Connection) getConfirmedScriptHistory( ) ([]*electrum.GetMempoolResult, error) { return client.GetHistory(ctx, reversedScriptHashString) }) - elapsed := time.Since(startTime) if err != nil { return nil, fmt.Errorf( - "failed to get history for script [0x%x] after [%s]: [%v]", + "failed to get history for script [0x%x]: [%v]", script, - elapsed, err, ) } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "GetHistory", - elapsed, - ) - // According to https://electrumx.readthedocs.io/en/latest/protocol-methods.html#blockchain-scripthash-get-history // unconfirmed items living in the mempool are appended at the end of the // returned list and their height value is either -1 or 0. That means @@ -644,9 +554,6 @@ func (c *Connection) getScriptMempool( reversedScriptHash := byteutils.Reverse(scriptHash[:]) reversedScriptHashString := hex.EncodeToString(reversedScriptHash) - logger.Infof("starting [%s] call to Electrum server", "GetMempool") - - startTime := time.Now() items, err := requestWithRetry( c, func( @@ -655,7 +562,6 @@ func (c *Connection) getScriptMempool( ) ([]*electrum.GetMempoolResult, error) { return client.GetMempool(ctx, reversedScriptHashString) }) - elapsed := time.Since(startTime) if err != nil { return nil, fmt.Errorf( "failed to get mempool for script [0x%x]: [%v]", @@ -664,11 +570,6 @@ func (c *Connection) getScriptMempool( ) } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "GetMempool", - elapsed, - ) - convertedItems := make([]*scriptMempoolItem, len(items)) for i, item := range items { txHash, err := bitcoin.NewHashFromString( @@ -696,9 +597,6 @@ func (c *Connection) getScriptMempool( // EstimateSatPerVByteFee returns the estimated sat/vbyte fee for a // transaction to be confirmed within the given number of blocks. func (c *Connection) EstimateSatPerVByteFee(blocks uint32) (int64, error) { - logger.Infof("starting [%s] call to Electrum server", "GetFee") - - startTime := time.Now() // According to Electrum protocol docs, the returned fee is BTC/KB. btcPerKbFee, err := requestWithRetry( c, @@ -713,19 +611,10 @@ func (c *Connection) EstimateSatPerVByteFee(blocks uint32) (int64, error) { // somehow once it disappears from Electrum implementations. return client.GetFee(ctx, blocks) }) - elapsed := time.Since(startTime) if err != nil { - return 0, fmt.Errorf("failed to get fee after [%s]: [%v]", - elapsed, - err, - ) + return 0, fmt.Errorf("failed to get fee: [%v]", err) } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "GetFee", - elapsed, - ) - // According to Electrum protocol docs, if the daemon does not have // enough information to make an estimate, the integer -1 is returned. if btcPerKbFee < 0 { @@ -770,9 +659,7 @@ func (c *Connection) verifyServer() error { version string protocol string } - logger.Infof("starting [%s] call to Electrum server", "ServerVersion") - startTime := time.Now() server, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (*Server, error) { @@ -783,19 +670,10 @@ func (c *Connection) verifyServer() error { return &Server{serverVersion, protocolVersion}, nil }, ) - elapsed := time.Since(startTime) if err != nil { - return fmt.Errorf("failed to get server version after [%s]: [%w]", - elapsed, - err, - ) + return fmt.Errorf("failed to get server version: [%w]", err) } - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "ServerVersion", - elapsed, - ) - logger.Infof( "connected to electrum server [version: [%s], protocol: [%s]]", server.version, @@ -821,30 +699,21 @@ func (c *Connection) keepAlive() { for { select { case <-ticker.C: - logger.Infof("starting [%s] call to Electrum server", "Ping") - - startTime := time.Now() _, err := requestWithRetry( c, func(ctx context.Context, client *electrum.Client) (interface{}, error) { return nil, client.Ping(ctx) }, ) - elapsed := time.Since(startTime) if err != nil { logger.Errorf( - "failed to ping the electrum server after [%s]; "+ + "failed to ping the electrum server; "+ "please verify health of the electrum server: [%v]", - elapsed, err, ) } else { // Adjust ticker starting at the time of the latest successful ping. ticker = time.NewTicker(c.config.KeepAliveInterval) - logger.Infof("successfully completed [%s] call to Electrum server after [%s]", - "Ping", - elapsed, - ) } case <-c.parentCtx.Done(): ticker.Stop() From 7fbb5ca0aee500f3e81bbe61b112df775fa0cdd0 Mon Sep 17 00:00:00 2001 From: Dmitry Date: Thu, 14 Sep 2023 12:59:27 +0200 Subject: [PATCH 4/4] 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. --- pkg/bitcoin/electrum/electrum.go | 53 +++++++++++++++++++++++++++----- 1 file changed, 45 insertions(+), 8 deletions(-) diff --git a/pkg/bitcoin/electrum/electrum.go b/pkg/bitcoin/electrum/electrum.go index 73ee50b41f..15d2acf0ce 100644 --- a/pkg/bitcoin/electrum/electrum.go +++ b/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 }