Improve signer broadcasting & logging

pkg/contracts/ton/gateway_msg.go

@@ -24,6 +24,15 @@ const (
 
 const OpWithdraw Op = 200
 
+// ExitCode represents an error code. Might be TVM or custom.
+// TVM: https://docs.ton.org/v3/documentation/tvm/tvm-exit-codes
+// Zeta: https://github.com/zeta-chain/protocol-contracts-ton/blob/main/contracts/common/errors.fc
+type ExitCode uint32
+
+const (
+	ExitCodeInvalidSeqno ExitCode = 109
+)
+
 // Donation represents a donation operation
 type Donation struct {
 	Sender ton.AccountID

zetaclient/chains/ton/signer/signer.go

@@ -2,10 +2,14 @@ package signer
 
 import (
 	"context"
+	"regexp"
+	"strconv"
+	"strings"
 
 	ethcommon "github.com/ethereum/go-ethereum/common"
 	lru "github.com/hashicorp/golang-lru"
 	"github.com/pkg/errors"
+	"github.com/tonkeeper/tongo/liteclient"
 	"github.com/tonkeeper/tongo/tlb"
 	"github.com/tonkeeper/tongo/ton"
 
@@ -84,13 +88,19 @@ func (s *Signer) TryProcessOutbound(
 	}()
 
 	outcome, err := s.ProcessOutbound(ctx, cctx, zetacore, zetaBlockHeight)
-	if err != nil {
-		s.Logger().Std.Error().
-			Err(err).
+	switch {
+	case err != nil:
+		s.Logger().Std.Error().Err(err).
 			Str("outbound.id", outboundID).
 			Uint64("outbound.nonce", cctx.GetCurrentOutboundParam().TssNonce).
 			Str("outbound.outcome", string(outcome)).
 			Msg("Unable to ProcessOutbound")
+	case outcome != Success:
+		s.Logger().Std.Warn().
+			Str("outbound.id", outboundID).
+			Uint64("outbound.nonce", cctx.GetCurrentOutboundParam().TssNonce).
+			Str("outbound.outcome", string(outcome)).
+			Msg("Unsuccessful outcome for ProcessOutbound")
 	}
 }
 
@@ -147,16 +157,8 @@ func (s *Signer) ProcessOutbound(
 	// Example: If a cctx has amount of 5 TON, the recipient will receive 5 TON,
 	// and gateway's balance will be decreased by 5 TON + txFees.
 	exitCode, err := s.gateway.SendExternalMessage(ctx, s.client, withdrawal)
-	switch {
-	case err != nil:
-		return Fail, errors.Wrap(err, "unable to send external message")
-	case exitCode != 0:
-		// Might happen if msg's nonce is too high; retry later.
-		lf["outbound.exit_code"] = exitCode
-		lf["outbound.outcome"] = string(Invalid)
-		s.Logger().Std.Info().Fields(lf).Msg("Unable to send external message")
-
-		return Invalid, nil
+	if err != nil || exitCode != 0 {
+		return s.handleSendError(exitCode, err, lf)
 	}
 
 	// it's okay to run this in the same goroutine
@@ -211,6 +213,62 @@ func (s *Signer) setSignature(hash [32]byte, sig [65]byte) {
 	s.signaturesCache.Add(hash, sig)
 }
 
+// Sample (from local ton):
+// error code: 0 message: cannot apply external message to current state:
+// External message was not accepted Cannot run message on account:
+// inbound external message rejected by transaction ...: exitcode=109, steps=108, gas_used=0\
+// VM Log (truncated): ...
+var exitCodeErrorRegex = regexp.MustCompile(`exitcode=(\d+)`)
+
+// handleSendError tries to figure out the reason of the send error.
+func (s *Signer) handleSendError(exitCode uint32, err error, logFields map[string]any) (Outcome, error) {
+	if err != nil {
+		// Might be possible if 2 concurrent zeta clients
+		// are trying to broadcast the same message.
+		if strings.Contains(err.Error(), "duplicate message") {
+			s.Logger().Std.Warn().Fields(logFields).Msg("Message already sent")
+			return Invalid, nil
+		}
+
+		var errLiteClient liteclient.LiteServerErrorC
+		if errors.As(err, &errLiteClient) {
+			logFields["outbound.error.message"] = errLiteClient.Message
+			exitCode = errLiteClient.Code
+		}
+
+		if code, ok := extractExitCode(err.Error()); ok {
+			exitCode = code
+		}
+	}
+
+	switch {
+	case exitCode == uint32(toncontracts.ExitCodeInvalidSeqno):
+		// Might be possible if zeta clients send several seq. numbers concurrently.
+		// In the current implementation, Gateway supports only 1 nonce per block.
+		logFields["outbound.error.exit_code"] = exitCode
+		s.Logger().Std.Warn().Fields(logFields).Msg("Invalid nonce, retry later")
+		return Invalid, nil
+	case err != nil:
+		return Fail, errors.Wrap(err, "unable to send external message")
+	default:
+		return Fail, errors.Errorf("unable to send external message: exit code %d", exitCode)
+	}
+}
+
+func extractExitCode(text string) (uint32, bool) {
+	match := exitCodeErrorRegex.FindStringSubmatch(text)
+	if len(match) < 2 {
+		return 0, false
+	}
+
+	exitCode, err := strconv.ParseUint(match[1], 10, 32)
+	if err != nil {
+		return 0, false
+	}
+
+	return uint32(exitCode), true
+}
+
 // GetGatewayAddress returns gateway address as raw TON address "0:ABC..."
 func (s *Signer) GetGatewayAddress() string {
 	return s.gateway.AccountID().ToRaw()

zetaclient/chains/ton/signer/signer_test.go

@@ -85,6 +85,31 @@ func TestSigner(t *testing.T) {
 	require.Equal(t, liteapi.TransactionToHashString(withdrawalTX), tracker.hash)
 }
 
+func TestExitCodeRegex(t *testing.T) {
+	for _, tt := range []string{
+		`unable to send external message: error code: 0 message: 
+		cannot apply external message to current state : 
+		External message was not accepted\nCannot run message on account: inbound external message rejected by 
+		transaction CC8803E21EDA7E6487D191380725A82CD75316E1C131496E1A5636751CE60347:
+		\nexitcode=109, steps=108, gas_used=0\nVM Log (truncated):\n...INT 0\nexecute THROWIFNOT 
+		105\nexecute MYADDR\nexecute XCHG s1,s4\nexecute SDEQ\nexecute THROWIF 112\nexecute OVER\nexecute 
+		EQINT 0\nexecute THROWIF 106\nexecute GETGLOB
+		3\nexecute NEQ\nexecute THROWIF 109\ndefault exception handler, terminating vm with exit code 109\n`,
+
+		`unable to send external message: error code: 0 message: cannot apply external message to current state : 
+		External message was not accepted\nCannot run message on account: 
+		inbound external message rejected by transaction 
+		6CCBB83C7D9BFBFDB40541F35AD069714856F18B4850C1273A117DF6BFADE1C6:\nexitcode=109, steps=108, 
+		gas_used=0\nVM Log (truncated):\n...INT 0....`,
+	} {
+		require.True(t, exitCodeErrorRegex.MatchString(tt))
+
+		exitCode, ok := extractExitCode(tt)
+		require.True(t, ok)
+		require.Equal(t, uint32(109), exitCode)
+	}
+}
+
 type testSuite struct {
 	ctx context.Context
 	t   *testing.T

zetaclient/orchestrator/orchestrator.go

@@ -756,7 +756,12 @@ func (oc *Orchestrator) ScheduleCCTXTON(
 		}
 
 		// fire async task
-		taskLogger := oc.logger.Logger.With().Str("outbound.id", outboundID).Logger()
+		taskLogger := oc.logger.Logger.With().
+			Int64(logs.FieldChain, chainID).
+			Str("outbound.id", outboundID).
+			Uint64("outbound.nonce", cctx.GetCurrentOutboundParam().TssNonce).
+			Logger()
+
 		bg.Work(ctx, task, bg.WithName("TryProcessOutbound"), bg.WithLogger(taskLogger))
 	}
 }