Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Logs for electrum connection #3715

Merged
merged 4 commits into from
Sep 14, 2023
Merged

Logs for electrum connection #3715

Changes from 2 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
e4795db
Removing a TODO comments because the issue was resolved
dimpar Sep 13, 2023
678a2ff
Adding logger around electrum client calls
dimpar Sep 14, 2023
d768be0
Revert "Adding logger around electrum client calls"
dimpar Sep 14, 2023
7fbb5ca
Adding logger around electrum client calls
dimpar Sep 14, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
157 changes: 142 additions & 15 deletions pkg/bitcoin/electrum/electrum.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand Down Expand Up @@ -86,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 @@ -94,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]",
lukasz-zimnoch marked this conversation as resolved.
Show resolved Hide resolved
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 @@ -122,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 @@ -130,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 @@ -171,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 @@ -179,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 @@ -237,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 @@ -256,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 @@ -266,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 @@ -283,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 @@ -292,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 @@ -313,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 @@ -326,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 @@ -427,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 @@ -435,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 @@ -558,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 @@ -566,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 @@ -574,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 @@ -601,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 @@ -615,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 @@ -663,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 @@ -674,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 @@ -703,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
Loading