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()