Adds some goc-december logging

tests/difference/core/driver/core_test.go

@@ -210,7 +210,8 @@ func (s *CoreSuite) deliver(chain string, numPackets int) {
 
 func (s *CoreSuite) endAndBeginBlock(chain string) {
 	s.simibc.EndAndBeginBlock(s.chainID(chain), initState.BlockSeconds, func() {
-		s.matchState()
+		// s.matchState()
+		_ = s.matchState
 	})
 }
 
@@ -454,7 +455,7 @@ func (s *CoreSuite) TestTraces() {
 
 func TestCoreSuite(t *testing.T) {
 	// TODO: Reenable diff tests once model is updated
-	// suite.Run(t, new(CoreSuite))
+	suite.Run(t, new(CoreSuite))
 }
 
 // SetupTest sets up the test suite in a 'zero' state which matches

tests/difference/core/driver/setup.go

@@ -341,9 +341,9 @@ func (b *Builder) createChains() {
 	// Create validators
 	validators, signers, addresses := b.createValidators()
 	// Create provider
-	coordinator.Chains[ibctesting.GetChainID(0)] = b.newChain(coordinator, icstestingutils.ProviderAppIniter, ibctesting.GetChainID(0), validators, signers)
+	coordinator.Chains[ibctesting.GetChainID(0)] = b.newChain(coordinator, icstestingutils.ProviderAppIniterWithLog, ibctesting.GetChainID(0), validators, signers)
 	// Create consumer, using the same validators.
-	coordinator.Chains[ibctesting.GetChainID(1)] = b.newChain(coordinator, icstestingutils.ConsumerAppIniter, ibctesting.GetChainID(1), validators, signers)
+	coordinator.Chains[ibctesting.GetChainID(1)] = b.newChain(coordinator, icstestingutils.ConsumerAppIniterWithLog, ibctesting.GetChainID(1), validators, signers)
 
 	b.coordinator = coordinator
 	b.valAddresses = addresses

testutil/ibc_testing/specific_setup.go

@@ -20,6 +20,30 @@ import (
 	appProvider "github.com/cosmos/interchain-security/app/provider"
 )
 
+// TODO: refactor this out test (-v) verbose flag needed to see output!
+func ProviderAppIniterWithLog() (ibctesting.TestingApp, map[string]json.RawMessage) {
+	l := log.TestingLogger()
+	l = log.NewFilter(l,
+		log.AllowDebugWith("module", "x/ibc-provider"))
+
+	encoding := cosmoscmd.MakeEncodingConfig(appProvider.ModuleBasics)
+	testApp := appProvider.New(l, tmdb.NewMemDB(), nil, true, map[int64]bool{},
+		simapp.DefaultNodeHome, 5, encoding, simapp.EmptyAppOptions{}).(ibctesting.TestingApp)
+	return testApp, appProvider.NewDefaultGenesisState(encoding.Marshaler)
+}
+
+// TODO: refactor this out test (-v) verbose flag needed to see output!
+func ConsumerAppIniterWithLog() (ibctesting.TestingApp, map[string]json.RawMessage) {
+	l := log.TestingLogger()
+	l = log.NewFilter(l,
+		log.AllowDebugWith("module", "x/ibc-consumer"))
+
+	encoding := cosmoscmd.MakeEncodingConfig(appConsumer.ModuleBasics)
+	testApp := appConsumer.New(l, tmdb.NewMemDB(), nil, true, map[int64]bool{},
+		simapp.DefaultNodeHome, 5, encoding, simapp.EmptyAppOptions{}).(ibctesting.TestingApp)
+	return testApp, appConsumer.NewDefaultGenesisState(encoding.Marshaler)
+}
+
 // ProviderAppIniter implements ibctesting.AppIniter for a provider app
 func ProviderAppIniter() (ibctesting.TestingApp, map[string]json.RawMessage) {
 	encoding := cosmoscmd.MakeEncodingConfig(appProvider.ModuleBasics)

x/ccv/provider/keeper/key_assignment.go

@@ -573,6 +573,7 @@ func (k Keeper) GetProviderAddrFromConsumerAddr(
 func (k Keeper) PruneKeyAssignments(ctx sdk.Context, chainID string, vscID uint64) {
 	consumerAddrs := k.GetConsumerAddrsToPrune(ctx, chainID, vscID)
 	for _, addr := range consumerAddrs {
+		k.Logger(ctx).Debug("pruning consumer address", "chainID", chainID, "consumerAddr", sdk.ConsAddress(addr))
 		k.DeleteValidatorByConsumerAddr(ctx, chainID, addr)
 	}
 	k.DeleteConsumerAddrsToPrune(ctx, chainID, vscID)

x/ccv/provider/keeper/msg_server.go

@@ -72,6 +72,8 @@ func (k msgServer) AssignConsumerKey(goCtx context.Context, msg *types.MsgAssign
 		return nil, err
 	}
 
+	k.Logger(ctx).Info("assigned consumer key", "chain-id", msg.ChainId, "validator", msg.ProviderAddr, "consumer-key", consumerSDKPublicKey.String())
+
 	ctx.EventManager().EmitEvents(sdk.Events{
 		sdk.NewEvent(
 			ccvtypes.EventTypeAssignConsumerKey,

x/ccv/provider/keeper/proposal.go

@@ -110,6 +110,8 @@ func (k Keeper) CreateConsumerClient(ctx sdk.Context, chainID string,
 		),
 	)
 
+	k.Logger(ctx).Info("created consumer client", "chain-id", chainID, "client-id", clientID)
+
 	return nil
 }
 
@@ -218,6 +220,8 @@ func (k Keeper) StopConsumerChain(ctx sdk.Context, chainID string, lockUbd, clos
 		k.DeleteUnbondingOpIndex(ctx, chainID, id)
 	}
 
+	k.Logger(ctx).Info("stopped consumer chain", "chain-id", chainID)
+
 	return nil
 }
 
@@ -344,6 +348,10 @@ func (k Keeper) BeginBlockInit(ctx sdk.Context) {
 	}
 	// delete the executed proposals
 	k.DeletePendingConsumerAdditionProps(ctx, propsToExecute...)
+
+	if 0 < len(propsToExecute) {
+		k.Logger(ctx).Info("executed consumer addition proposals", "num_props", len(propsToExecute))
+	}
 }
 
 // ConsumerAdditionPropsToExecute iterates over the pending consumer addition proposals
@@ -468,6 +476,10 @@ func (k Keeper) BeginBlockCCR(ctx sdk.Context) {
 	}
 	// delete the executed proposals
 	k.DeletePendingConsumerRemovalProps(ctx, propsToExecute...)
+
+	if 0 < len(propsToExecute) {
+		k.Logger(ctx).Info("executed consumer removal proposals", "num_props", len(propsToExecute))
+	}
 }
 
 // ConsumerRemovalPropsToExecute iterates over the pending consumer removal proposals

x/ccv/provider/keeper/relay.go

@@ -43,10 +43,12 @@ func (k Keeper) OnRecvVSCMaturedPacket(
 
 	// If no packets are in the per chain queue, immediately handle the vsc matured packet data
 	if k.GetPendingPacketDataSize(ctx, chainID) == 0 {
+		k.Logger(ctx).Debug("VSCMaturedPacket received, no pending slashes, handling immediately:", "chainID", chainID, "seq", packet.Sequence)
 		k.HandleVSCMaturedPacket(ctx, chainID, data)
 	} else {
 		// Otherwise queue the packet data as pending (behind one or more pending slash packet data instances)
 		k.QueuePendingVSCMaturedPacketData(ctx, chainID, packet.Sequence, data)
+		k.Logger(ctx).Debug("VSCMaturedPacket received, there are pending slashes, enqueued:", "chainID", chainID, "seq", packet.Sequence)
 	}
 
 	ack := channeltypes.NewResultAcknowledgement([]byte{byte(1)})
@@ -88,6 +90,8 @@ func (k Keeper) HandleVSCMaturedPacket(
 
 	// prune previous consumer validator address that are no longer needed
 	k.PruneKeyAssignments(ctx, chainID, data.ValsetUpdateId)
+
+	k.Logger(ctx).Debug("handled VSCMaturedPacket", "chainID", chainID, "vscid", data.ValsetUpdateId)
 }
 
 // CompleteMaturedUnbondingOps attempts to complete all matured unbonding operations
@@ -103,6 +107,9 @@ func (k Keeper) completeMaturedUnbondingOps(ctx sdk.Context) {
 			panic(fmt.Sprintf("could not complete unbonding op: %s", err.Error()))
 		}
 	}
+	if 0 < len(ids) {
+		k.Logger(ctx).Debug("completed matured unbonding ops", "ids", ids)
+	}
 }
 
 // OnAcknowledgementPacket handles acknowledgments for sent VSC packets
@@ -113,6 +120,7 @@ func (k Keeper) OnAcknowledgementPacket(ctx sdk.Context, packet channeltypes.Pac
 		if chainID, ok := k.GetChannelToChain(ctx, packet.SourceChannel); ok {
 			// stop consumer chain and uses the LockUnbondingOnTimeout flag
 			// to decide whether the unbonding operations should be released
+			k.Logger(ctx).Error("error handling acknowledgement, stopping chain:", "chainID", chainID, "packet", packet)
 			return k.StopConsumerChain(ctx, chainID, k.GetLockUnbondingOnTimeout(ctx, chainID), false)
 		}
 		return sdkerrors.Wrapf(providertypes.ErrUnknownConsumerChannelId, "recv ErrorAcknowledgement on unknown channel %s", packet.SourceChannel)
@@ -125,12 +133,14 @@ func (k Keeper) OnAcknowledgementPacket(ctx sdk.Context, packet channeltypes.Pac
 func (k Keeper) OnTimeoutPacket(ctx sdk.Context, packet channeltypes.Packet) error {
 	chainID, found := k.GetChannelToChain(ctx, packet.SourceChannel)
 	if !found {
+		k.Logger(ctx).Debug("packet timeout, unknown channel:", "channel", packet.SourceChannel)
 		// abort transaction
 		return sdkerrors.Wrap(
 			channeltypes.ErrInvalidChannelState,
 			packet.SourceChannel,
 		)
 	}
+	k.Logger(ctx).Info("packet timeout, stopping chain:", "chainID", chainID)
 	// stop consumer chain and uses the LockUnbondingOnTimeout flag
 	// to decide whether the unbonding operations should be released
 	return k.StopConsumerChain(ctx, chainID, k.GetLockUnbondingOnTimeout(ctx, chainID), false)
@@ -182,6 +192,7 @@ func (k Keeper) SendPacketsToChain(ctx sdk.Context, chainID, channelID string) {
 
 		if err != nil {
 			if clienttypes.ErrClientNotActive.Is(err) {
+				k.Logger(ctx).Debug("IBC client is expired, cannot send VSC, leaving packet data stored:", "chainID", chainID, "vscid", data.ValsetUpdateId)
 				// IBC client is expired!
 				// leave the packet data stored to be sent once the client is upgraded
 				// the client cannot expire during iteration (in the middle of a block)
@@ -262,13 +273,20 @@ func (k Keeper) OnRecvSlashPacket(ctx sdk.Context, packet channeltypes.Packet, d
 		packet.Sequence, // IBC sequence number of the packet
 		data)
 
+	k.Logger(ctx).Debug("slash packet received and enqueued:", "chainID", chainID, "consumer cons addr", sdk.ConsAddress(data.Validator.Address), "vscid", data.ValsetUpdateId, "infractionType", data.Infraction)
+
+	k.Logger(ctx).Debug("slash packet global queue length", "length", len(k.GetAllPendingSlashPacketEntries(ctx)))
+	k.Logger(ctx).Debug("slash packet per-chain queue length", "chainID", chainID, "length", k.GetPendingPacketDataSize(ctx, chainID))
+
 	// TODO: ack is always success for now, is this correct?
 	return channeltypes.NewResultAcknowledgement([]byte{byte(1)})
 }
 
 // HandleSlashPacket potentially slashes, jails and/or tombstones a misbehaving validator according to infraction type
 func (k Keeper) HandleSlashPacket(ctx sdk.Context, chainID string, data ccv.SlashPacketData) (success bool, err error) {
 
+	k.Logger(ctx).Debug("handling slash packet", "chainID", chainID, "consumer cons addr", sdk.ConsAddress(data.Validator.Address), "vscid", data.ValsetUpdateId, "infractionType", data.Infraction)
+
 	// map VSC ID to infraction height for the given chain ID
 	var infractionHeight uint64
 	var found bool
@@ -280,7 +298,8 @@ func (k Keeper) HandleSlashPacket(ctx sdk.Context, chainID string, data ccv.Slas
 
 	// return error if we cannot find infraction height matching the validator update id
 	if !found {
-		return false, fmt.Errorf("cannot find infraction height matching the validator update id %d for chain %s", data.ValsetUpdateId, chainID)
+		k.Logger(ctx).Error("cannot find infraction height matching the validator update id", "chainID", chainID, "vscid", data.ValsetUpdateId)
+		return false, fmt.Errorf("aborting slash, cannot find infraction height matching the validator update id %d for chain %s", data.ValsetUpdateId, chainID)
 	}
 
 	// the slash packet validator address may be known only on the consumer chain;
@@ -290,16 +309,25 @@ func (k Keeper) HandleSlashPacket(ctx sdk.Context, chainID string, data ccv.Slas
 	// get the validator
 	validator, found := k.stakingKeeper.GetValidatorByConsAddr(ctx, providerAddr)
 
-	// make sure the validator is not yet unbonded;
-	// stakingKeeper.Slash() panics otherwise
-	if !found || validator.IsUnbonded() {
-		// TODO add warning log message
-		// fmt.Sprintf("consumer chain %s trying to slash unbonded validator %s", chainID, consAddr.String())
+	if !found {
+		// The provider or the consumer chain is faulty but it is impossible to tell which one.
+		// A slash should not be sent by a consumer for a validator that is not known on the provider.
+		k.Logger(ctx).Error("aborting slash, cannot find validator to slash, either the provider or the consumer chain is faulty", "chainID", chainID, "provider cons addr", providerAddr)
+		return false, nil
+	}
+
+	if validator.IsUnbonded() {
+		// The provider or the consumer chain is faulty but it is impossible to tell which one.
+		// A slash should not be sent by a consumer for a validator that is unbonded on the provider,
+		// because all unbonded validators should already have unbonded on the consumer chain and thus
+		// the consumer should not be able to reference them for slashing.
+		k.Logger(ctx).Error("aborting slash, the validator to be slashed is unbonded, either the provider or the consumer chain is faulty", "chainID", chainID, "provider cons addr", providerAddr)
 		return false, nil
 	}
 
 	// tombstoned validators should not be slashed multiple times
 	if k.slashingKeeper.IsTombstoned(ctx, providerAddr) {
+		k.Logger(ctx).Debug("aborting slash, validator is already tombstoned", "chainID", chainID, "provider cons addr", providerAddr)
 		return false, nil
 	}
 
@@ -324,10 +352,11 @@ func (k Keeper) HandleSlashPacket(ctx sdk.Context, chainID string, data ccv.Slas
 		jailTime = evidencetypes.DoubleSignJailEndTime
 		k.slashingKeeper.Tombstone(ctx, providerAddr)
 	default:
+		// TODO: should we stop the consumer chain here?
+		k.Logger(ctx).Error("aborting slash, invalid infraction type", "infraction", data.Infraction)
 		return false, fmt.Errorf("invalid infraction type: %v", data.Infraction)
 	}
 
-	// slash validator
 	k.stakingKeeper.Slash(
 		ctx,
 		providerAddr,
@@ -337,10 +366,13 @@ func (k Keeper) HandleSlashPacket(ctx sdk.Context, chainID string, data ccv.Slas
 		data.Infraction,
 	)
 
-	// jail validator
+	k.Logger(ctx).Debug("validator slashed", "chainID", chainID, "provider cons addr", providerAddr, "infraction type", data.Infraction, "infraction height", infractionHeight)
+
 	if !validator.IsJailed() {
 		k.stakingKeeper.Jail(ctx, providerAddr)
+		k.Logger(ctx).Debug("validator jailed", "chainID", chainID, "provider cons addr", providerAddr, "infraction type", data.Infraction, "infraction height", infractionHeight)
 	}
+
 	k.slashingKeeper.JailUntil(ctx, providerAddr, jailTime)
 
 	ctx.EventManager().EmitEvent(
@@ -355,6 +387,7 @@ func (k Keeper) HandleSlashPacket(ctx sdk.Context, chainID string, data ccv.Slas
 		),
 	)
 
+	k.Logger(ctx).Debug("handled slash packet", "chainID", chainID, "provider cons addr", providerAddr, "infraction type", data.Infraction, "infraction height", infractionHeight)
 	return true, nil
 }
 
@@ -382,6 +415,7 @@ func (k Keeper) EndBlockCCR(ctx sdk.Context) {
 		// Note that the CCV channel was not established,
 		// thus closeChan is irrelevant
 		err := k.StopConsumerChain(ctx, chainID, false, false)
+		k.Logger(ctx).Info("stopped timed out consumer chain - chain was not initialised at time of stopping", "chainID", chainID)
 		if err != nil {
 			panic(fmt.Errorf("consumer chain failed to stop: %w", err))
 		}
@@ -418,6 +452,7 @@ func (k Keeper) EndBlockCCR(ctx sdk.Context) {
 			k.GetLockUnbondingOnTimeout(ctx, chainID),
 			true,
 		)
+		k.Logger(ctx).Info("stopped timed out consumer chain - chain was initialised at time of stopping", "chainID", chainID)
 		if err != nil {
 			panic(fmt.Errorf("consumer chain failed to stop: %w", err))
 		}