diff --git a/internal/db/delegation.go b/internal/db/delegation.go index 40769c6..6bb7702 100644 --- a/internal/db/delegation.go +++ b/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() diff --git a/internal/db/interface.go b/internal/db/interface.go index 50888fc..7e64cb2 100644 --- a/internal/db/interface.go +++ b/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 diff --git a/internal/services/delegation.go b/internal/services/delegation.go index a9c9496..49bfcea 100644 --- a/internal/services/delegation.go +++ b/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.Debug(). + 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 { diff --git a/internal/services/delegation_helpers.go b/internal/services/delegation_helpers.go index e8fdc9f..1619197 100644 --- a/internal/services/delegation_helpers.go +++ b/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.Debug(). + 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.Debug(). + Str("staking_tx", delegation.StakingTxHashHex). + Msg("registering staking spend notification") + stakingOutpoint := wire.OutPoint{ Hash: *stakingTxHash, Index: delegation.StakingOutputIdx, diff --git a/internal/services/expiry_checker.go b/internal/services/expiry_checker.go index 804a8e2..c81c49f 100644 --- a/internal/services/expiry_checker.go +++ b/internal/services/expiry_checker.go @@ -44,12 +44,17 @@ func (s *Service) checkExpiry(ctx context.Context) *types.Error { ) } + log.Debug(). + 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), ) diff --git a/internal/services/watch_btc_events.go b/internal/services/watch_btc_events.go index d2ce161..85ab354 100644 --- a/internal/services/watch_btc_events.go +++ b/internal/services/watch_btc_events.go @@ -30,6 +30,10 @@ func (s *Service) watchForSpendStakingTx( // Get spending details select { case spendDetail := <-spendEvent.Spend: + log.Debug(). + 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, @@ -37,7 +41,11 @@ func (s *Service) watchForSpendStakingTx( 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,6 +68,10 @@ func (s *Service) watchForSpendUnbondingTx( // Get spending details select { case spendDetail := <-spendEvent.Spend: + log.Debug(). + 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, @@ -67,7 +79,11 @@ func (s *Service) watchForSpendUnbondingTx( 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 } @@ -89,19 +105,25 @@ func (s *Service) watchForSpendSlashingChange( select { case spendDetail := <-spendEvent.Spend: - log.Info(). - Str("delegation", delegation.StakingTxHashHex). + log.Debug(). + 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.Debug(). + 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.Debug(). + 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.Debug(). + 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.Debug(). + 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.Debug(). + 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(), diff --git a/internal/types/state.go b/internal/types/state.go index 0a8d4a8..bd61c82 100644 --- a/internal/types/state.go +++ b/internal/types/state.go @@ -53,7 +53,9 @@ 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 @@ -61,16 +63,13 @@ 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 ( - SubStateTimelock DelegationSubState = "TIMELOCK" - SubStateEarlyUnbonding DelegationSubState = "EARLY_UNBONDING" + SubStateTimelock DelegationSubState = "TIMELOCK" + SubStateEarlyUnbonding DelegationSubState = "EARLY_UNBONDING" + + // Used only for Withdrawable and Withdrawn parent states SubStateTimelockSlashing DelegationSubState = "TIMELOCK_SLASHING" SubStateEarlyUnbondingSlashing DelegationSubState = "EARLY_UNBONDING_SLASHING" ) diff --git a/tests/mocks/mock_db_client.go b/tests/mocks/mock_db_client.go index 1ae5142..8a2179c 100644 --- a/tests/mocks/mock_db_client.go +++ b/tests/mocks/mock_db_client.go @@ -359,17 +359,17 @@ func (_m *DbInterface) UpdateBTCDelegationDetails(ctx context.Context, stakingTx return r0 } -// UpdateBTCDelegationState provides a mock function with given fields: ctx, stakingTxHash, newState, subState -func (_m *DbInterface) UpdateBTCDelegationState(ctx context.Context, stakingTxHash string, newState types.DelegationState, subState *types.DelegationSubState) error { - ret := _m.Called(ctx, stakingTxHash, newState, subState) +// UpdateBTCDelegationState provides a mock function with given fields: ctx, stakingTxHash, qualifiedPreviousStates, newState, newSubState +func (_m *DbInterface) UpdateBTCDelegationState(ctx context.Context, stakingTxHash string, qualifiedPreviousStates []types.DelegationState, newState types.DelegationState, newSubState *types.DelegationSubState) error { + ret := _m.Called(ctx, stakingTxHash, qualifiedPreviousStates, newState, newSubState) if len(ret) == 0 { panic("no return value specified for UpdateBTCDelegationState") } var r0 error - if rf, ok := ret.Get(0).(func(context.Context, string, types.DelegationState, *types.DelegationSubState) error); ok { - r0 = rf(ctx, stakingTxHash, newState, subState) + if rf, ok := ret.Get(0).(func(context.Context, string, []types.DelegationState, types.DelegationState, *types.DelegationSubState) error); ok { + r0 = rf(ctx, stakingTxHash, qualifiedPreviousStates, newState, newSubState) } else { r0 = ret.Error(0) }