Add debugging logs

smartcontractkit · Oct 31, 2024 · 6392027 · 6392027
1 parent dd39cc0
commit 6392027
Show file tree

Hide file tree

Showing 5 changed files with 24 additions and 7 deletions.
diff --git a/integration-tests/testconfig/testconfig.go b/integration-tests/testconfig/testconfig.go
@@ -267,7 +267,8 @@ func (c *TestConfig) GetNodeConfigTOML() (string, error) {
 
 	mnConfig := solcfg.MultiNodeConfig{
 		MultiNode: solcfg.MultiNode{
-			Enabled: ptr.Ptr(true),
+			Enabled:       ptr.Ptr(true),
+			SyncThreshold: ptr.Ptr(uint32(170)),
 		},
 	}
 	mnConfig.SetDefaults()
@@ -283,6 +284,7 @@ func (c *TestConfig) GetNodeConfigTOML() (string, error) {
 	chainCfg := solcfg.Chain{
 		// Increase timeout for TransactionSender
 		TxTimeout: config.MustNewDuration(2 * time.Minute),
+		// TODO: Increase TxRetryTimeout?
 	}
 	chainCfg.SetDefaults()
 

diff --git a/pkg/solana/client/client.go b/pkg/solana/client/client.go
@@ -242,6 +242,11 @@ func (c *Client) SendTx(ctx context.Context, tx *solana.Transaction) (solana.Sig
 	done := c.latency("send_tx")
 	defer done()
 
+	elapsedTime := time.Now()
+	defer func() {
+		c.log.Debugw("Client SendTx() elapsed time", "time", time.Since(elapsedTime).Seconds())
+	}()
+	c.log.Debugw("Client SendTx()", "timeout", c.txTimeout)
 	ctx, cancel := context.WithTimeout(ctx, c.txTimeout)
 	defer cancel()
 

diff --git a/pkg/solana/client/multinode/multi_node.go b/pkg/solana/client/multinode/multi_node.go
@@ -90,15 +90,14 @@ func (c *MultiNode[CHAIN_ID, RPC]) ChainID() CHAIN_ID {
 	return c.chainID
 }
 
-func (c *MultiNode[CHAIN_ID, RPC]) DoAll(baseCtx context.Context, do func(ctx context.Context, rpc RPC, isSendOnly bool)) error {
+func (c *MultiNode[CHAIN_ID, RPC]) DoAll(ctx context.Context, do func(ctx context.Context, rpc RPC, isSendOnly bool)) error {
 	var err error
 	ok := c.IfNotStopped(func() {
-		ctx, _ := c.chStop.Ctx(baseCtx)
-
 		callsCompleted := 0
 		for _, n := range c.primaryNodes {
 			select {
 			case <-ctx.Done():
+				c.lggr.Errorw("DoAll: Context done on primary node", "err", ctx.Err())
 				err = ctx.Err()
 				return
 			default:
@@ -118,6 +117,7 @@ func (c *MultiNode[CHAIN_ID, RPC]) DoAll(baseCtx context.Context, do func(ctx co
 		for _, n := range c.sendOnlyNodes {
 			select {
 			case <-ctx.Done():
+				c.lggr.Errorw("DoAll: Context done on send only node", "err", ctx.Err())
 				err = ctx.Err()
 				return
 			default:

diff --git a/pkg/solana/client/multinode/transaction_sender.go b/pkg/solana/client/multinode/transaction_sender.go
@@ -92,6 +92,7 @@ type TransactionSender[TX any, RESULT SendTxResult, CHAIN_ID ID, RPC SendTxRPCCl
 // * If there is both success and terminal error - returns success and reports invariant violation
 // * Otherwise, returns any (effectively random) of the errors.
 func (txSender *TransactionSender[TX, RESULT, CHAIN_ID, RPC]) SendTransaction(ctx context.Context, tx TX) RESULT {
+	startTime := time.Now()
 	txResults := make(chan RESULT)
 	txResultsToReport := make(chan RESULT)
 	primaryNodeWg := sync.WaitGroup{}
@@ -146,13 +147,14 @@ func (txSender *TransactionSender[TX, RESULT, CHAIN_ID, RPC]) SendTransaction(ct
 	}()
 
 	if err != nil {
+		txSender.lggr.Errorw("Failed to broadcast transaction", "tx", tx, "err", err)
 		return txSender.newResult(err)
 	}
 
 	txSender.wg.Add(1)
 	go txSender.reportSendTxAnomalies(tx, txResultsToReport)
 
-	return txSender.collectTxResults(ctx, tx, healthyNodesNum, txResults)
+	return txSender.collectTxResults(ctx, tx, healthyNodesNum, txResults, startTime)
 }
 
 func (txSender *TransactionSender[TX, RESULT, CHAIN_ID, RPC]) broadcastTxAsync(ctx context.Context, rpc RPC, tx TX) RESULT {
@@ -210,7 +212,7 @@ func aggregateTxResults[RESULT any](resultsByCode sendTxResults[RESULT]) (result
 	return result, criticalErr
 }
 
-func (txSender *TransactionSender[TX, RESULT, CHAIN_ID, RPC]) collectTxResults(ctx context.Context, tx TX, healthyNodesNum int, txResults <-chan RESULT) RESULT {
+func (txSender *TransactionSender[TX, RESULT, CHAIN_ID, RPC]) collectTxResults(ctx context.Context, tx TX, healthyNodesNum int, txResults <-chan RESULT, startTime time.Time) RESULT {
 	if healthyNodesNum == 0 {
 		return txSender.newResult(ErroringNodeError)
 	}
@@ -222,7 +224,7 @@ loop:
 	for {
 		select {
 		case <-ctx.Done():
-			txSender.lggr.Debugw("Failed to collect of the results before context was done", "tx", tx, "errorsByCode", errorsByCode)
+			txSender.lggr.Debugw("Failed to collect of the results before context was done", "tx", tx, "errorsByCode", errorsByCode, "elapsedTime", time.Since(startTime).Seconds())
 			return txSender.newResult(ctx.Err())
 		case r := <-txResults:
 			errorsByCode[r.Code()] = append(errorsByCode[r.Code()], r)

diff --git a/pkg/solana/client/multinode_client.go b/pkg/solana/client/multinode_client.go
@@ -354,6 +354,14 @@ func (r *SendTxResult) Signature() solana.Signature {
 }
 
 func (m *MultiNodeClient) SendTransaction(ctx context.Context, tx *solana.Transaction) *SendTxResult {
+	// TODO: Debugging check if ctx is already cancelled
+	select {
+	case <-ctx.Done():
+		// TODO: This context would be from the TxSenderCtx and not sendTx()
+		m.log.Errorf("SendTransaction: context already cancelled")
+	default:
+		break
+	}
 	var sendTxResult = &SendTxResult{}
 	sendTxResult.sig, sendTxResult.txErr = m.SendTx(ctx, tx)
 	sendTxResult.code = ClassifySendError(tx, sendTxResult.txErr)