fix: withdrawn state issue

.github/workflows/publish.yml

@@ -4,6 +4,7 @@ on:
   push:
     branches:
     - 'main'
+    - 'gusin13/debug-withdrawn-not-done'
     tags:
     - '*'
 

internal/db/delegation.go

@@ -38,16 +38,30 @@ func (db *Database) SaveNewBTCDelegation(
 func (db *Database) UpdateBTCDelegationState(
 	ctx context.Context,
 	stakingTxHash string,
+	qualifiedPreviousStates []types.DelegationState,
 	newState types.DelegationState,
-	subState *types.DelegationSubState,
+	newSubState *types.DelegationSubState,
 ) error {
-	filter := bson.M{"_id": stakingTxHash}
+	if len(qualifiedPreviousStates) == 0 {
+		return fmt.Errorf("qualified previous states array cannot be empty")
+	}
+
+	qualifiedStateStrs := make([]string, len(qualifiedPreviousStates))
+	for i, state := range qualifiedPreviousStates {
+		qualifiedStateStrs[i] = state.String()
+	}
+
+	filter := bson.M{
+		"_id":   stakingTxHash,
+		"state": bson.M{"$in": qualifiedStateStrs},
+	}
+
 	updateFields := bson.M{
 		"state": newState.String(),
 	}
 
-	if subState != nil {
-		updateFields["sub_state"] = subState.String()
+	if newSubState != nil {
+		updateFields["sub_state"] = newSubState.String()
 	}
 
 	update := bson.M{
@@ -62,7 +76,7 @@ func (db *Database) UpdateBTCDelegationState(
 		if errors.Is(res.Err(), mongo.ErrNoDocuments) {
 			return &NotFoundError{
 				Key:     stakingTxHash,
-				Message: "BTC delegation not found when updating state",
+				Message: "BTC delegation not found or current state is not qualified states",
 			}
 		}
 		return res.Err()

internal/db/interface.go

@@ -100,8 +100,9 @@ type DbInterface interface {
 	UpdateBTCDelegationState(
 		ctx context.Context,
 		stakingTxHash string,
+		qualifiedPreviousStates []types.DelegationState,
 		newState types.DelegationState,
-		subState *types.DelegationSubState,
+		newSubState *types.DelegationSubState,
 	) error
 	/**
 	 * SaveBTCDelegationUnbondingCovenantSignature saves a BTC delegation

internal/services/delegation.go

@@ -12,6 +12,7 @@ import (
 	bbntypes "github.com/babylonlabs-io/babylon/x/btcstaking/types"
 	ftypes "github.com/babylonlabs-io/babylon/x/finality/types"
 	abcitypes "github.com/cometbft/cometbft/abci/types"
+	"github.com/rs/zerolog/log"
 )
 
 const (
@@ -160,6 +161,7 @@ func (s *Service) processCovenantQuorumReachedEvent(
 	if dbErr := s.db.UpdateBTCDelegationState(
 		ctx,
 		covenantQuorumReachedEvent.StakingTxHash,
+		types.QualifiedStatesForCovenantQuorumReached(covenantQuorumReachedEvent.NewState),
 		newState,
 		nil,
 	); dbErr != nil {
@@ -282,10 +284,20 @@ func (s *Service) processBTCDelegationUnbondedEarlyEvent(
 		)
 	}
 
+	log.Info().
+		Str("staking_tx", unbondedEarlyEvent.StakingTxHash).
+		Str("new_state", types.StateUnbonding.String()).
+		Str("early_unbonding_start_height", unbondedEarlyEvent.StartHeight).
+		Str("unbonding_time", strconv.FormatUint(uint64(delegation.UnbondingTime), 10)).
+		Str("unbonding_expire_height", strconv.FormatUint(uint64(unbondingExpireHeight), 10)).
+		Str("sub_state", subState.String()).
+		Msg("updating delegation state to early unbonding")
+
 	// Update delegation state
 	if err := s.db.UpdateBTCDelegationState(
 		ctx,
 		unbondedEarlyEvent.StakingTxHash,
+		types.QualifiedStatesForUnbondedEarly(),
 		types.StateUnbonding,
 		&subState,
 	); err != nil {
@@ -358,6 +370,7 @@ func (s *Service) processBTCDelegationExpiredEvent(
 	if err := s.db.UpdateBTCDelegationState(
 		ctx,
 		delegation.StakingTxHashHex,
+		types.QualifiedStatesForExpired(),
 		types.StateUnbonding,
 		&subState,
 	); err != nil {

internal/services/delegation_helpers.go

@@ -12,6 +12,7 @@ import (
 	bbn "github.com/babylonlabs-io/babylon/types"
 	"github.com/btcsuite/btcd/chaincfg/chainhash"
 	"github.com/btcsuite/btcd/wire"
+	"github.com/rs/zerolog/log"
 )
 
 func (s *Service) registerUnbondingSpendNotification(
@@ -36,6 +37,11 @@ func (s *Service) registerUnbondingSpendNotification(
 		)
 	}
 
+	log.Info().
+		Str("staking_tx", delegation.StakingTxHashHex).
+		Str("unbonding_tx", unbondingTx.TxHash().String()).
+		Msg("registering early unbonding spend notification")
+
 	unbondingOutpoint := wire.OutPoint{
 		Hash:  unbondingTx.TxHash(),
 		Index: 0, // unbonding tx has only 1 output
@@ -82,6 +88,10 @@ func (s *Service) registerStakingSpendNotification(
 		)
 	}
 
+	log.Info().
+		Str("staking_tx", delegation.StakingTxHashHex).
+		Msg("registering staking spend notification")
+
 	stakingOutpoint := wire.OutPoint{
 		Hash:  *stakingTxHash,
 		Index: delegation.StakingOutputIdx,

internal/services/expiry_checker.go

@@ -44,12 +44,17 @@ func (s *Service) checkExpiry(ctx context.Context) *types.Error {
 			)
 		}
 
+		log.Info().
+			Str("staking_tx", delegation.StakingTxHashHex).
+			Str("current_state", delegation.State.String()).
+			Msg("checking if delegation is expired")
+
 		// Check if the delegation is in a qualified state to transition to Withdrawable
 		if !utils.Contains(types.QualifiedStatesForWithdrawable(), delegation.State) {
 			log.Debug().
-				Str("stakingTxHashHex", delegation.StakingTxHashHex).
-				Str("currentState", delegation.State.String()).
-				Msg("Ignoring expired delegation as it is not qualified to transition to Withdrawable")
+				Str("staking_tx", delegation.StakingTxHashHex).
+				Str("current_state", delegation.State.String()).
+				Msg("current state is not qualified for withdrawable")
 			continue
 		}
 
@@ -61,17 +66,22 @@ func (s *Service) checkExpiry(ctx context.Context) *types.Error {
 		if err := s.db.UpdateBTCDelegationState(
 			ctx,
 			delegation.StakingTxHashHex,
+			types.QualifiedStatesForWithdrawable(),
 			types.StateWithdrawable,
 			&tlDoc.DelegationSubState,
 		); err != nil {
-			log.Error().Err(err).Msg("Error updating BTC delegation state to withdrawable")
+			log.Error().
+				Str("staking_tx", delegation.StakingTxHashHex).
+				Msg("failed to update BTC delegation state to withdrawable")
 			return types.NewInternalServiceError(
 				fmt.Errorf("failed to update BTC delegation state to withdrawable: %w", err),
 			)
 		}
 
 		if err := s.db.DeleteExpiredDelegation(ctx, delegation.StakingTxHashHex); err != nil {
-			log.Error().Err(err).Msg("Error deleting expired delegation")
+			log.Error().
+				Str("staking_tx", delegation.StakingTxHashHex).
+				Msg("failed to delete expired delegation")
 			return types.NewInternalServiceError(
 				fmt.Errorf("failed to delete expired delegation: %w", err),
 			)

internal/services/watch_btc_events.go

@@ -30,14 +30,22 @@ func (s *Service) watchForSpendStakingTx(
 	// Get spending details
 	select {
 	case spendDetail := <-spendEvent.Spend:
+		log.Info().
+			Str("staking_tx", delegation.StakingTxHashHex).
+			Str("spending_tx", spendDetail.SpendingTx.TxHash().String()).
+			Msg("staking tx has been spent")
 		if err := s.handleSpendingStakingTransaction(
 			quitCtx,
 			spendDetail.SpendingTx,
 			spendDetail.SpenderInputIndex,
 			uint32(spendDetail.SpendingHeight),
 			delegation,
 		); err != nil {
-			log.Error().Err(err).Msg("failed to handle spending staking transaction")
+			log.Error().
+				Err(err).
+				Str("staking_tx", delegation.StakingTxHashHex).
+				Str("spending_tx", spendDetail.SpendingTx.TxHash().String()).
+				Msg("failed to handle spending staking transaction")
 			return
 		}
 
@@ -60,14 +68,22 @@ func (s *Service) watchForSpendUnbondingTx(
 	// Get spending details
 	select {
 	case spendDetail := <-spendEvent.Spend:
+		log.Info().
+			Str("staking_tx", delegation.StakingTxHashHex).
+			Str("unbonding_tx", spendDetail.SpendingTx.TxHash().String()).
+			Msg("unbonding tx has been spent")
 		if err := s.handleSpendingUnbondingTransaction(
 			quitCtx,
 			spendDetail.SpendingTx,
 			uint32(spendDetail.SpendingHeight),
 			spendDetail.SpenderInputIndex,
 			delegation,
 		); err != nil {
-			log.Error().Err(err).Msg("failed to handle spending unbonding transaction")
+			log.Error().
+				Err(err).
+				Str("staking_tx", delegation.StakingTxHashHex).
+				Str("unbonding_tx", spendDetail.SpendingTx.TxHash().String()).
+				Msg("failed to handle spending unbonding transaction")
 			return
 		}
 
@@ -90,18 +106,24 @@ func (s *Service) watchForSpendSlashingChange(
 	select {
 	case spendDetail := <-spendEvent.Spend:
 		log.Info().
-			Str("delegation", delegation.StakingTxHashHex).
+			Str("staking_tx", delegation.StakingTxHashHex).
 			Str("spending_tx", spendDetail.SpendingTx.TxHash().String()).
 			Msg("slashing change output has been spent")
 		delegationState, err := s.db.GetBTCDelegationState(quitCtx, delegation.StakingTxHashHex)
 		if err != nil {
-			log.Error().Err(err).Msg("failed to get delegation state")
+			log.Error().
+				Err(err).
+				Str("staking_tx", delegation.StakingTxHashHex).
+				Msg("failed to get delegation state")
 			return
 		}
 
-		qualifiedStates := types.QualifiedStatesForSlashedWithdrawn()
+		qualifiedStates := types.QualifiedStatesForWithdrawn()
 		if qualifiedStates == nil || !utils.Contains(qualifiedStates, *delegationState) {
-			log.Error().Msgf("current state %s is not qualified for slashed withdrawn", *delegationState)
+			log.Error().
+				Str("staking_tx", delegation.StakingTxHashHex).
+				Str("state", delegationState.String()).
+				Msg("current state is not qualified for slashed withdrawn")
 			return
 		}
 
@@ -110,10 +132,16 @@ func (s *Service) watchForSpendSlashingChange(
 		if err := s.db.UpdateBTCDelegationState(
 			quitCtx,
 			delegation.StakingTxHashHex,
+			types.QualifiedStatesForWithdrawn(),
 			types.StateWithdrawn,
 			&delegationSubState,
 		); err != nil {
-			log.Error().Err(err).Msg("failed to update delegation state")
+			log.Error().
+				Err(err).
+				Str("staking_tx", delegation.StakingTxHashHex).
+				Str("state", types.StateWithdrawn.String()).
+				Str("sub_state", delegationSubState.String()).
+				Msg("failed to update delegation state to withdrawn")
 			return
 		}
 
@@ -142,6 +170,10 @@ func (s *Service) handleSpendingStakingTransaction(
 		return fmt.Errorf("failed to validate unbonding tx: %w", err)
 	}
 	if isUnbonding {
+		log.Info().
+			Str("staking_tx", delegation.StakingTxHashHex).
+			Str("unbonding_tx", spendingTx.TxHash().String()).
+			Msg("staking tx has been spent through unbonding path")
 		// It's a valid unbonding tx, no further action needed at this stage
 		return nil
 	}
@@ -150,6 +182,10 @@ func (s *Service) handleSpendingStakingTransaction(
 	withdrawalErr := s.validateWithdrawalTxFromStaking(spendingTx, spendingInputIdx, delegation, params)
 	if withdrawalErr == nil {
 		// It's a valid withdrawal, process it
+		log.Info().
+			Str("staking_tx", delegation.StakingTxHashHex).
+			Str("withdrawal_tx", spendingTx.TxHash().String()).
+			Msg("staking tx has been spent through withdrawal path")
 		return s.handleWithdrawal(ctx, delegation, types.SubStateTimelock)
 	}
 
@@ -193,6 +229,10 @@ func (s *Service) handleSpendingUnbondingTransaction(
 	withdrawalErr := s.validateWithdrawalTxFromUnbonding(spendingTx, delegation, spendingInputIdx, params)
 	if withdrawalErr == nil {
 		// It's a valid withdrawal, process it
+		log.Info().
+			Str("staking_tx", delegation.StakingTxHashHex).
+			Str("unbonding_tx", spendingTx.TxHash().String()).
+			Msg("unbonding tx has been spent through withdrawal path")
 		return s.handleWithdrawal(ctx, delegation, types.SubStateEarlyUnbonding)
 	}
 
@@ -232,13 +272,23 @@ func (s *Service) handleWithdrawal(
 
 	qualifiedStates := types.QualifiedStatesForWithdrawn()
 	if qualifiedStates == nil || !utils.Contains(qualifiedStates, *delegationState) {
+		log.Error().
+			Str("staking_tx", delegation.StakingTxHashHex).
+			Str("current_state", delegationState.String()).
+			Msg("current state is not qualified for withdrawal")
 		return fmt.Errorf("current state %s is not qualified for withdrawal", *delegationState)
 	}
 
 	// Update to withdrawn state
+	log.Info().
+		Str("staking_tx", delegation.StakingTxHashHex).
+		Str("state", types.StateWithdrawn.String()).
+		Str("sub_state", subState.String()).
+		Msg("updating delegation state to withdrawn")
 	return s.db.UpdateBTCDelegationState(
 		ctx,
 		delegation.StakingTxHashHex,
+		types.QualifiedStatesForWithdrawn(),
 		types.StateWithdrawn,
 		&subState,
 	)
@@ -251,6 +301,11 @@ func (s *Service) startWatchingSlashingChange(
 	delegation *model.BTCDelegationDetails,
 	subState types.DelegationSubState,
 ) error {
+	log.Info().
+		Str("staking_tx", delegation.StakingTxHashHex).
+		Str("slashing_tx", slashingTx.TxHash().String()).
+		Msg("watching for slashing change output")
+
 	// Create outpoint for the change output (index 1)
 	changeOutpoint := wire.OutPoint{
 		Hash:  slashingTx.TxHash(),

internal/types/state.go

@@ -53,19 +53,16 @@ func QualifiedStatesForExpired() []DelegationState {
 
 // QualifiedStatesForWithdrawn returns the qualified current states for Withdrawn event
 func QualifiedStatesForWithdrawn() []DelegationState {
-	return []DelegationState{StateWithdrawable}
+	// StateUnbonding is included because its possible that expiry checker is slow
+	// and in meanwhile the btc subscription encounters the spending/withdrawal tx
+	return []DelegationState{StateUnbonding, StateWithdrawable}
 }
 
 // QualifiedStatesForWithdrawable returns the qualified current states for Withdrawable event
 func QualifiedStatesForWithdrawable() []DelegationState {
 	return []DelegationState{StateUnbonding}
 }
 
-// QualifiedStatesForSlashedWithdrawn returns the qualified current states for SlashedWithdrawn event
-func QualifiedStatesForSlashedWithdrawn() []DelegationState {
-	return []DelegationState{StateSlashed}
-}
-
 type DelegationSubState string
 
 const (