add provider and consumer logging

tests/integration/actions.go

@@ -499,7 +499,7 @@ gas_multiplier = 1.1
 grpc_addr = "%s"
 id = "%s"
 key_name = "%s"
-max_gas = 2000000
+max_gas = 20000000
 rpc_addr = "%s"
 rpc_timeout = "10s"
 store_prefix = "ibc"

x/ccv/consumer/keeper/distribution.go

@@ -85,6 +85,11 @@ func (k Keeper) DistributeToProviderValidatorSet(ctx sdk.Context) error {
 				return err
 			}
 		}
+
+		k.Logger(ctx).Info("sent block rewards to provider",
+			"total", fpTokens.String(),
+			"to provider", remainingTokens.String(),
+		)
 	}
 
 	newLtbh := types.LastTransmissionBlockHeight{

x/ccv/consumer/keeper/relay.go

@@ -35,6 +35,7 @@ func (k Keeper) OnRecvVSCPacket(ctx sdk.Context, packet channeltypes.Packet, new
 		// the first packet from the provider chain
 		// - mark the CCV channel as established
 		k.SetProviderChannel(ctx, packet.DestinationChannel)
+		k.Logger(ctx).Info("CCV channel established", "port", packet.DestinationPort, "channel", packet.DestinationChannel)
 
 		// emit event on first VSC packet to signal that CCV is working
 		ctx.EventManager().EmitEvent(
@@ -65,16 +66,28 @@ func (k Keeper) OnRecvVSCPacket(ctx sdk.Context, packet channeltypes.Packet, new
 	// Save maturity time and packet
 	maturityTime := ctx.BlockTime().Add(k.GetUnbondingPeriod(ctx))
 	k.SetPacketMaturityTime(ctx, newChanges.ValsetUpdateId, maturityTime)
+	k.Logger(ctx).Debug("packet maturity time was set",
+		"vscID", newChanges.ValsetUpdateId,
+		"ts (utc)", maturityTime.UTC(),
+		"ts (nano)", uint64(maturityTime.UnixNano()),
+	)
 
 	// set height to VSC id mapping
-	k.SetHeightValsetUpdateID(ctx, uint64(ctx.BlockHeight())+1, newChanges.ValsetUpdateId)
+	blockHeight := uint64(ctx.BlockHeight()) + 1
+	k.SetHeightValsetUpdateID(ctx, blockHeight, newChanges.ValsetUpdateId)
+	k.Logger(ctx).Debug("block height was mapped to vscID", "height", blockHeight, "vscID", newChanges.ValsetUpdateId)
 
 	// remove outstanding slashing flags of the validators
 	// for which the slashing was acknowledged by the provider chain
 	for _, addr := range newChanges.GetSlashAcks() {
 		k.DeleteOutstandingDowntime(ctx, addr)
 	}
 
+	k.Logger(ctx).Info("finished receiving/handling VSCPacket",
+		"vscID", newChanges.ValsetUpdateId,
+		"len updates", len(newChanges.ValidatorUpdates),
+		"len slash acks", len(newChanges.SlashAcks),
+	)
 	ack := channeltypes.NewResultAcknowledgement([]byte{byte(1)})
 	return ack
 }
@@ -102,6 +115,8 @@ func (k Keeper) QueueVSCMaturedPackets(ctx sdk.Context) {
 
 		k.DeletePacketMaturityTimes(ctx, maturityTime.VscId, maturityTime.MaturityTime)
 
+		k.Logger(ctx).Info("VSCMaturedPacket enqueued", "vscID", vscPacket.ValsetUpdateId)
+
 		ctx.EventManager().EmitEvent(
 			sdk.NewEvent(
 				ccv.EventTypeVSCMatured,
@@ -143,6 +158,12 @@ func (k Keeper) QueueSlashPacket(ctx sdk.Context, validator abci.Validator, vals
 		},
 	})
 
+	k.Logger(ctx).Info("SlashPacket enqueued",
+		"vscID", slashPacket.ValsetUpdateId,
+		"validator cons addr", sdk.ConsAddress(slashPacket.Validator.Address).String(),
+		"infraction", slashPacket.Infraction,
+	)
+
 	ctx.EventManager().EmitEvent(
 		sdk.NewEvent(
 			ccv.EventTypeConsumerSlashRequest,
@@ -185,6 +206,7 @@ func (k Keeper) SendPackets(ctx sdk.Context) {
 
 		if err != nil {
 			if clienttypes.ErrClientNotActive.Is(err) {
+				k.Logger(ctx).Debug("IBC client is inactive, packet remains in queue", "type", p.Type.String())
 				// leave the packet data stored to be sent once the client is upgraded
 				return
 			}
@@ -204,7 +226,7 @@ func (k Keeper) OnAcknowledgementPacket(ctx sdk.Context, packet channeltypes.Pac
 	if err := ack.GetError(); err != "" {
 		// Reasons for ErrorAcknowledgment
 		//  - packet data could not be successfully decoded
-		//  - the Slash packet was ill-formed (errors while handling it)
+		//  - invalid Slash packet
 		// None of these should ever happen.
 		k.Logger(ctx).Error(
 			"recv ErrorAcknowledgement",

x/ccv/consumer/keeper/validators.go

@@ -85,13 +85,20 @@ func (k Keeper) Slash(ctx sdk.Context, addr sdk.ConsAddress, infractionHeight, p
 		return
 	}
 
+	// get VSC ID for infraction height
+	vscID := k.GetHeightValsetUpdateID(ctx, uint64(infractionHeight))
+
+	k.Logger(ctx).Debug("map infraction height to vscID",
+		"infraction height", infractionHeight,
+		"vscID", vscID,
+	)
+
 	k.QueueSlashPacket(
 		ctx,
 		abci.Validator{
 			Address: addr.Bytes(),
 			Power:   power},
-		// get VSC ID for infraction height
-		k.GetHeightValsetUpdateID(ctx, uint64(infractionHeight)),
+		vscID,
 		infraction,
 	)
 }

x/ccv/consumer/module.go

@@ -159,13 +159,14 @@ func (am AppModule) BeginBlock(ctx sdk.Context, req abci.RequestBeginBlock) {
 		// the consumer chain is no longer safe
 
 		channelClosedMsg := fmt.Sprintf("CCV channel %q was closed - shutdown consumer chain since it is not secured anymore", channelID)
-		ctx.Logger().Error(channelClosedMsg)
+		am.keeper.Logger(ctx).Error(channelClosedMsg)
 		panic(channelClosedMsg)
 	}
 
-	blockHeight := uint64(ctx.BlockHeight())
+	blockHeight := uint64(ctx.BlockHeight()) + 1
 	vID := am.keeper.GetHeightValsetUpdateID(ctx, blockHeight)
-	am.keeper.SetHeightValsetUpdateID(ctx, blockHeight+1, vID)
+	am.keeper.SetHeightValsetUpdateID(ctx, blockHeight, vID)
+	am.keeper.Logger(ctx).Debug("block height was mapped to vscID", "height", blockHeight, "vscID", vID)
 
 	am.keeper.TrackHistoricalInfo(ctx)
 }
@@ -179,7 +180,7 @@ func (am AppModule) EndBlock(ctx sdk.Context, req abci.RequestEndBlock) []abci.V
 		panic(err)
 	}
 
-	// NOTE: Slash packets are queued in BeginBlock
+	// NOTE: Slash packets are queued in BeginBlock via the Slash function
 	// Packet ordering is managed by the PendingPackets queue.
 	am.keeper.QueueVSCMaturedPackets(ctx)
 
@@ -194,6 +195,8 @@ func (am AppModule) EndBlock(ctx sdk.Context, req abci.RequestEndBlock) []abci.V
 	tendermintUpdates := am.keeper.ApplyCCValidatorChanges(ctx, data.ValidatorUpdates)
 	am.keeper.DeletePendingChanges(ctx)
 
+	am.keeper.Logger(ctx).Debug("sending validator updates to consensus engine", "len updates", len(tendermintUpdates))
+
 	return tendermintUpdates
 }
 

x/ccv/provider/keeper/key_assignment.go

@@ -536,7 +536,12 @@ func (k Keeper) PruneKeyAssignments(ctx sdk.Context, chainID string, vscID uint6
 	consumerAddrs := k.GetConsumerAddrsToPrune(ctx, chainID, vscID)
 	for _, addr := range consumerAddrs.Addresses {
 		k.DeleteValidatorByConsumerAddr(ctx, chainID, addr)
+		k.Logger(ctx).Info("consumer address was pruned",
+			"chainID", chainID,
+			"consumerAddr", sdk.ConsAddress(addr).String(),
+		)
 	}
+
 	k.DeleteConsumerAddrsToPrune(ctx, chainID, vscID)
 }
 

x/ccv/provider/keeper/msg_server.go

@@ -71,6 +71,11 @@ func (k msgServer) AssignConsumerKey(goCtx context.Context, msg *types.MsgAssign
 	if err := k.Keeper.AssignConsumerKey(ctx, msg.ChainId, validator, consumerTMPublicKey); err != nil {
 		return nil, err
 	}
+	k.Logger(ctx).Info("assigned consumer key",
+		"chainID", msg.ChainId,
+		"validator", msg.ProviderAddr,
+		"consumer-key", consumerSDKPublicKey.String(),
+	)
 
 	ctx.EventManager().EmitEvents(sdk.Events{
 		sdk.NewEvent(

x/ccv/provider/keeper/proposal.go

@@ -37,6 +37,12 @@ func (k Keeper) HandleConsumerAdditionProposal(ctx sdk.Context, p *types.Consume
 
 	k.SetPendingConsumerAdditionProp(ctx, p)
 
+	k.Logger(ctx).Info("consumer addition proposal enqueued",
+		"chainID", p.ChainId,
+		"title", p.Title,
+		"spawn time", p.SpawnTime.UTC(),
+	)
+
 	return nil
 }
 
@@ -95,6 +101,11 @@ func (k Keeper) CreateConsumerClient(ctx sdk.Context, prop *types.ConsumerAdditi
 	ts := ctx.BlockTime().Add(k.GetParams(ctx).InitTimeoutPeriod)
 	k.SetInitTimeoutTimestamp(ctx, chainID, uint64(ts.UnixNano()))
 
+	k.Logger(ctx).Info("consumer chain registered (client created)",
+		"chainID", chainID,
+		"clientID", clientID,
+	)
+
 	ctx.EventManager().EmitEvent(
 		sdk.NewEvent(
 			ccv.EventTypeConsumerClientCreated,
@@ -125,6 +136,13 @@ func (k Keeper) HandleConsumerRemovalProposal(ctx sdk.Context, p *types.Consumer
 	}
 
 	k.SetPendingConsumerRemovalProp(ctx, p)
+
+	k.Logger(ctx).Info("consumer removal proposal enqueued",
+		"chainID", p.ChainId,
+		"title", p.Title,
+		"stop time", p.StopTime.UTC(),
+	)
+
 	return nil
 }
 
@@ -205,6 +223,8 @@ func (k Keeper) StopConsumerChain(ctx sdk.Context, chainID string, closeChan boo
 	// since all unbonding operations for this consumer are release above.
 	k.DeleteThrottledPacketDataForConsumer(ctx, chainID)
 
+	k.Logger(ctx).Info("consumer chain removed from provider", "chainID", chainID)
+
 	return nil
 }
 
@@ -351,6 +371,12 @@ func (k Keeper) BeginBlockInit(ctx sdk.Context) {
 		ctx.EventManager().EmitEvents(cachedCtx.EventManager().Events())
 		// write cache
 		writeFn()
+
+		k.Logger(ctx).Info("executed consumer addition proposal",
+			"chainID", prop.ChainId,
+			"title", prop.Title,
+			"spawn time", prop.SpawnTime.UTC(),
+		)
 	}
 	// delete the executed proposals
 	k.DeletePendingConsumerAdditionProps(ctx, propsToExecute...)
@@ -474,6 +500,12 @@ func (k Keeper) BeginBlockCCR(ctx sdk.Context) {
 		ctx.EventManager().EmitEvents(cachedCtx.EventManager().Events())
 		// write cache
 		writeFn()
+
+		k.Logger(ctx).Info("executed consumer removal proposal",
+			"chainID", prop.ChainId,
+			"title", prop.Title,
+			"stop time", prop.StopTime.UTC(),
+		)
 	}
 	// delete the executed proposals
 	k.DeletePendingConsumerRemovalProps(ctx, propsToExecute...)