Skip to content

Commit

Permalink
Adding logger around electrum client calls
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@dimpar
dimpar committed Sep 14, 2023
1 parent e4795db commit 678a2ff
Showing 1 changed file with 142 additions and 11 deletions.
153 changes: 142 additions & 11 deletions pkg/bitcoin/electrum/electrum.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand All @@ -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)
Expand All @@ -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) {
Expand All @@ -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(
Expand Down Expand Up @@ -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(
Expand All @@ -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
Expand Down Expand Up @@ -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)

Expand All @@ -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) {
Expand All @@ -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
}
Expand All @@ -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(
Expand All @@ -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)
Expand All @@ -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(
Expand All @@ -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
}

Expand Down Expand Up @@ -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(
Expand All @@ -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
Expand Down Expand Up @@ -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(
Expand All @@ -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]",
Expand All @@ -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(
Expand Down Expand Up @@ -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,
Expand All @@ -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 {
Expand Down Expand Up @@ -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) {
Expand All @@ -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,
Expand All @@ -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()
Expand Down

0 comments on commit 678a2ff

Please sign in to comment.