From 6b38711ea3631893e1672e62060bcdc7d928747b Mon Sep 17 00:00:00 2001 From: Cian Hatton Date: Mon, 9 Jan 2023 12:02:36 +0000 Subject: [PATCH] chore: Improved logging in IBC Core (#2976) --- internal/logging/logging.go | 23 +++++++ .../controller/keeper/account.go | 6 +- .../controller/keeper/migrations.go | 6 ++ .../controller/keeper/msg_server.go | 3 + .../host/keeper/handshake.go | 2 + modules/core/keeper/msg_server.go | 63 +++++++++++++++++++ 6 files changed, 102 insertions(+), 1 deletion(-) create mode 100644 internal/logging/logging.go diff --git a/internal/logging/logging.go b/internal/logging/logging.go new file mode 100644 index 00000000000..03a326a7d45 --- /dev/null +++ b/internal/logging/logging.go @@ -0,0 +1,23 @@ +package logging + +import ( + "fmt" + + sdk "github.com/cosmos/cosmos-sdk/types" +) + +// SdkEventsToLogArguments converts a given sdk.Events and returns a slice of strings that provide human +// readable values for the event attributes. +func SdkEventsToLogArguments(events sdk.Events) []string { + logArgs := []string{"events"} + for _, e := range events { + logArgs = append(logArgs, fmt.Sprintf("type=%s", e.Type)) + for _, attr := range e.Attributes { + if len(attr.Value) == 0 { + continue + } + logArgs = append(logArgs, fmt.Sprintf("%s=%s", attr.Key, attr.Value)) + } + } + return logArgs +} diff --git a/modules/apps/27-interchain-accounts/controller/keeper/account.go b/modules/apps/27-interchain-accounts/controller/keeper/account.go index 01d4922cbca..7bd3676f829 100644 --- a/modules/apps/27-interchain-accounts/controller/keeper/account.go +++ b/modules/apps/27-interchain-accounts/controller/keeper/account.go @@ -5,6 +5,7 @@ import ( sdkerrors "github.com/cosmos/cosmos-sdk/types/errors" authtypes "github.com/cosmos/cosmos-sdk/x/auth/types" + "github.com/cosmos/ibc-go/v6/internal/logging" icatypes "github.com/cosmos/ibc-go/v6/modules/apps/27-interchain-accounts/types" channeltypes "github.com/cosmos/ibc-go/v6/modules/core/04-channel/types" host "github.com/cosmos/ibc-go/v6/modules/core/24-host" @@ -72,8 +73,11 @@ func (k Keeper) registerInterchainAccount(ctx sdk.Context, connectionID, portID, return "", err } + events := res.GetEvents() + k.Logger(ctx).Debug("emitting interchain account registration events", logging.SdkEventsToLogArguments(events)) + // NOTE: The sdk msg handler creates a new EventManager, so events must be correctly propagated back to the current context - ctx.EventManager().EmitEvents(res.GetEvents()) + ctx.EventManager().EmitEvents(events) firstMsgResponse := res.MsgResponses[0] channelOpenInitResponse, ok := firstMsgResponse.GetCachedValue().(*channeltypes.MsgChannelOpenInitResponse) diff --git a/modules/apps/27-interchain-accounts/controller/keeper/migrations.go b/modules/apps/27-interchain-accounts/controller/keeper/migrations.go index 27e859070a0..3d7986cfbd0 100644 --- a/modules/apps/27-interchain-accounts/controller/keeper/migrations.go +++ b/modules/apps/27-interchain-accounts/controller/keeper/migrations.go @@ -1,6 +1,8 @@ package keeper import ( + "fmt" + sdk "github.com/cosmos/cosmos-sdk/types" sdkerrors "github.com/cosmos/cosmos-sdk/types/errors" capabilitytypes "github.com/cosmos/cosmos-sdk/x/capability/types" @@ -24,20 +26,24 @@ func NewMigrator(keeper *Keeper) Migrator { // are owned by the controller submodule and ibc. func (m Migrator) AssertChannelCapabilityMigrations(ctx sdk.Context) error { if m.keeper != nil { + logger := m.keeper.Logger(ctx) filteredChannels := m.keeper.channelKeeper.GetAllChannelsWithPortPrefix(ctx, icatypes.ControllerPortPrefix) for _, ch := range filteredChannels { name := host.ChannelCapabilityPath(ch.PortId, ch.ChannelId) capability, found := m.keeper.scopedKeeper.GetCapability(ctx, name) if !found { + logger.Error(fmt.Sprintf("failed to find capability: %s", name)) return sdkerrors.Wrapf(capabilitytypes.ErrCapabilityNotFound, "failed to find capability: %s", name) } isAuthenticated := m.keeper.scopedKeeper.AuthenticateCapability(ctx, capability, name) if !isAuthenticated { + logger.Error(fmt.Sprintf("expected capability owner: %s", controllertypes.SubModuleName)) return sdkerrors.Wrapf(capabilitytypes.ErrCapabilityNotOwned, "expected capability owner: %s", controllertypes.SubModuleName) } m.keeper.SetMiddlewareEnabled(ctx, ch.PortId, ch.ConnectionHops[0]) + logger.Info("successfully migrated channel capability", "name", name) } } return nil diff --git a/modules/apps/27-interchain-accounts/controller/keeper/msg_server.go b/modules/apps/27-interchain-accounts/controller/keeper/msg_server.go index 63a71dfa0ca..23bdcbfb4ba 100644 --- a/modules/apps/27-interchain-accounts/controller/keeper/msg_server.go +++ b/modules/apps/27-interchain-accounts/controller/keeper/msg_server.go @@ -39,9 +39,12 @@ func (s msgServer) RegisterInterchainAccount(goCtx context.Context, msg *types.M channelID, err := s.registerInterchainAccount(ctx, msg.ConnectionId, portID, msg.Version) if err != nil { + s.Logger(ctx).Error("error registering interchain account", "error", err.Error()) return nil, err } + s.Logger(ctx).Info("successfully registered interchain account", "channel-id", channelID) + return &types.MsgRegisterInterchainAccountResponse{ ChannelId: channelID, }, nil diff --git a/modules/apps/27-interchain-accounts/host/keeper/handshake.go b/modules/apps/27-interchain-accounts/host/keeper/handshake.go index e1c5ec7a6cc..faeb4ab9d23 100644 --- a/modules/apps/27-interchain-accounts/host/keeper/handshake.go +++ b/modules/apps/27-interchain-accounts/host/keeper/handshake.go @@ -78,6 +78,7 @@ func (k Keeper) OnChanOpenTry( interchainAccAddr, found := k.GetInterchainAccountAddress(ctx, metadata.HostConnectionId, counterparty.PortId) if found { // reopening an interchain account + k.Logger(ctx).Info("reopening existing interchain account", "address", interchainAccAddr) accAddress = sdk.MustAccAddressFromBech32(interchainAccAddr) if _, ok := k.accountKeeper.GetAccount(ctx, accAddress).(*icatypes.InterchainAccount); !ok { return "", sdkerrors.Wrapf(icatypes.ErrInvalidAccountReopening, "existing account address %s, does not have interchain account type", accAddress) @@ -88,6 +89,7 @@ func (k Keeper) OnChanOpenTry( if err != nil { return "", err } + k.Logger(ctx).Info("successfully created new interchain account", "host-connection-id", metadata.HostConnectionId, "port-id", counterparty.PortId, "address", accAddress) } metadata.Address = accAddress.String() diff --git a/modules/core/keeper/msg_server.go b/modules/core/keeper/msg_server.go index 7c15728a01f..051f52f3efb 100644 --- a/modules/core/keeper/msg_server.go +++ b/modules/core/keeper/msg_server.go @@ -169,12 +169,14 @@ func (k Keeper) ChannelOpenInit(goCtx context.Context, msg *channeltypes.MsgChan // Lookup module by port capability module, portCap, err := k.PortKeeper.LookupModuleByPort(ctx, msg.PortId) if err != nil { + ctx.Logger().Error("channel open init callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrap(err, "could not retrieve module from port-id")) return nil, sdkerrors.Wrap(err, "could not retrieve module from port-id") } // Retrieve application callbacks from router cbs, ok := k.Router.GetRoute(module) if !ok { + ctx.Logger().Error("channel open init callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module)) return nil, sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module) } @@ -184,18 +186,22 @@ func (k Keeper) ChannelOpenInit(goCtx context.Context, msg *channeltypes.MsgChan portCap, msg.Channel.Counterparty, msg.Channel.Version, ) if err != nil { + ctx.Logger().Error("channel open init callback failed", "error", sdkerrors.Wrap(err, "channel handshake open init failed")) return nil, sdkerrors.Wrap(err, "channel handshake open init failed") } // Perform application logic callback version, err := cbs.OnChanOpenInit(ctx, msg.Channel.Ordering, msg.Channel.ConnectionHops, msg.PortId, channelID, cap, msg.Channel.Counterparty, msg.Channel.Version) if err != nil { + ctx.Logger().Error("channel open init callback failed", "port-id", msg.PortId, "channel-id", channelID, "error", err.Error()) return nil, sdkerrors.Wrapf(err, "channel open init callback failed for port ID: %s, channel ID: %s", msg.PortId, channelID) } // Write channel into state k.ChannelKeeper.WriteOpenInitChannel(ctx, msg.PortId, channelID, msg.Channel.Ordering, msg.Channel.ConnectionHops, msg.Channel.Counterparty, version) + ctx.Logger().Info("channel open init callback succeeded", "channel-id", channelID, "version", version) + return &channeltypes.MsgChannelOpenInitResponse{ ChannelId: channelID, Version: version, @@ -211,12 +217,14 @@ func (k Keeper) ChannelOpenTry(goCtx context.Context, msg *channeltypes.MsgChann // Lookup module by port capability module, portCap, err := k.PortKeeper.LookupModuleByPort(ctx, msg.PortId) if err != nil { + ctx.Logger().Error("channel open try callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrap(err, "could not retrieve module from port-id")) return nil, sdkerrors.Wrap(err, "could not retrieve module from port-id") } // Retrieve application callbacks from router cbs, ok := k.Router.GetRoute(module) if !ok { + ctx.Logger().Error("channel open try callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module)) return nil, sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module) } @@ -225,18 +233,22 @@ func (k Keeper) ChannelOpenTry(goCtx context.Context, msg *channeltypes.MsgChann portCap, msg.Channel.Counterparty, msg.CounterpartyVersion, msg.ProofInit, msg.ProofHeight, ) if err != nil { + ctx.Logger().Error("channel open try callback failed", "error", sdkerrors.Wrap(err, "channel handshake open try failed")) return nil, sdkerrors.Wrap(err, "channel handshake open try failed") } // Perform application logic callback version, err := cbs.OnChanOpenTry(ctx, msg.Channel.Ordering, msg.Channel.ConnectionHops, msg.PortId, channelID, cap, msg.Channel.Counterparty, msg.CounterpartyVersion) if err != nil { + ctx.Logger().Error("channel open try callback failed", "port-id", msg.PortId, "channel-id", channelID, "error", err.Error()) return nil, sdkerrors.Wrapf(err, "channel open try callback failed for port ID: %s, channel ID: %s", msg.PortId, channelID) } // Write channel into state k.ChannelKeeper.WriteOpenTryChannel(ctx, msg.PortId, channelID, msg.Channel.Ordering, msg.Channel.ConnectionHops, msg.Channel.Counterparty, version) + ctx.Logger().Info("channel open try callback succeeded", "channel-id", channelID, "port-id", msg.PortId, "version", version) + return &channeltypes.MsgChannelOpenTryResponse{ Version: version, }, nil @@ -251,12 +263,14 @@ func (k Keeper) ChannelOpenAck(goCtx context.Context, msg *channeltypes.MsgChann // Lookup module by channel capability module, cap, err := k.ChannelKeeper.LookupModuleByChannel(ctx, msg.PortId, msg.ChannelId) if err != nil { + ctx.Logger().Error("channel open ack callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrap(err, "could not retrieve module from port-id")) return nil, sdkerrors.Wrap(err, "could not retrieve module from port-id") } // Retrieve application callbacks from router cbs, ok := k.Router.GetRoute(module) if !ok { + ctx.Logger().Error("channel open ack callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module)) return nil, sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module) } @@ -264,17 +278,21 @@ func (k Keeper) ChannelOpenAck(goCtx context.Context, msg *channeltypes.MsgChann if err = k.ChannelKeeper.ChanOpenAck( ctx, msg.PortId, msg.ChannelId, cap, msg.CounterpartyVersion, msg.CounterpartyChannelId, msg.ProofTry, msg.ProofHeight, ); err != nil { + ctx.Logger().Error("channel open ack callback failed", "error", err.Error()) return nil, sdkerrors.Wrap(err, "channel handshake open ack failed") } // Perform application logic callback if err = cbs.OnChanOpenAck(ctx, msg.PortId, msg.ChannelId, msg.CounterpartyChannelId, msg.CounterpartyVersion); err != nil { + ctx.Logger().Error("channel handshake open ack callback failed", "port-id", msg.PortId, "channel-id", msg.ChannelId, "error", err.Error()) return nil, sdkerrors.Wrapf(err, "channel open ack callback failed for port ID: %s, channel ID: %s", msg.PortId, msg.ChannelId) } // Write channel into state k.ChannelKeeper.WriteOpenAckChannel(ctx, msg.PortId, msg.ChannelId, msg.CounterpartyVersion, msg.CounterpartyChannelId) + ctx.Logger().Info("channel open ack callback succeeded", "channel-id", msg.ChannelId, "port-id", msg.PortId) + return &channeltypes.MsgChannelOpenAckResponse{}, nil } @@ -287,28 +305,34 @@ func (k Keeper) ChannelOpenConfirm(goCtx context.Context, msg *channeltypes.MsgC // Lookup module by channel capability module, cap, err := k.ChannelKeeper.LookupModuleByChannel(ctx, msg.PortId, msg.ChannelId) if err != nil { + ctx.Logger().Error("channel open confirm callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrap(err, "could not retrieve module from port-id")) return nil, sdkerrors.Wrap(err, "could not retrieve module from port-id") } // Retrieve application callbacks from router cbs, ok := k.Router.GetRoute(module) if !ok { + ctx.Logger().Error("channel open confirm callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module)) return nil, sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module) } // Perform 04-channel verification if err = k.ChannelKeeper.ChanOpenConfirm(ctx, msg.PortId, msg.ChannelId, cap, msg.ProofAck, msg.ProofHeight); err != nil { + ctx.Logger().Error("channel open confirm callback failed", "error", sdkerrors.Wrap(err, "channel handshake open confirm failed")) return nil, sdkerrors.Wrap(err, "channel handshake open confirm failed") } // Perform application logic callback if err = cbs.OnChanOpenConfirm(ctx, msg.PortId, msg.ChannelId); err != nil { + ctx.Logger().Error("channel handshake open confirm callback failed", "port-id", msg.PortId, "channel-id", msg.ChannelId, "error", err.Error()) return nil, sdkerrors.Wrapf(err, "channel open confirm callback failed for port ID: %s, channel ID: %s", msg.PortId, msg.ChannelId) } // Write channel into state k.ChannelKeeper.WriteOpenConfirmChannel(ctx, msg.PortId, msg.ChannelId) + ctx.Logger().Info("channel open confirm callback succeeded", "channel-id", msg.ChannelId, "port-id", msg.PortId) + return &channeltypes.MsgChannelOpenConfirmResponse{}, nil } @@ -318,24 +342,30 @@ func (k Keeper) ChannelCloseInit(goCtx context.Context, msg *channeltypes.MsgCha // Lookup module by channel capability module, cap, err := k.ChannelKeeper.LookupModuleByChannel(ctx, msg.PortId, msg.ChannelId) if err != nil { + ctx.Logger().Error("channel close init callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrap(err, "could not retrieve module from port-id")) return nil, sdkerrors.Wrap(err, "could not retrieve module from port-id") } // Retrieve callbacks from router cbs, ok := k.Router.GetRoute(module) if !ok { + ctx.Logger().Error("channel close init callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module)) return nil, sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module) } if err = cbs.OnChanCloseInit(ctx, msg.PortId, msg.ChannelId); err != nil { + ctx.Logger().Error("channel close init callback failed", "port-id", msg.PortId, "channel-id", msg.ChannelId, "error", err.Error()) return nil, sdkerrors.Wrapf(err, "channel close init callback failed for port ID: %s, channel ID: %s", msg.PortId, msg.ChannelId) } err = k.ChannelKeeper.ChanCloseInit(ctx, msg.PortId, msg.ChannelId, cap) if err != nil { + ctx.Logger().Error("channel handshake close init callback failed", "port-id", msg.PortId, "channel-id", msg.ChannelId, "error", err.Error()) return nil, sdkerrors.Wrap(err, "channel handshake close init failed") } + ctx.Logger().Info("channel close init callback succeeded", "channel-id", msg.ChannelId, "port-id", msg.PortId) + return &channeltypes.MsgChannelCloseInitResponse{}, nil } @@ -346,24 +376,30 @@ func (k Keeper) ChannelCloseConfirm(goCtx context.Context, msg *channeltypes.Msg // Lookup module by channel capability module, cap, err := k.ChannelKeeper.LookupModuleByChannel(ctx, msg.PortId, msg.ChannelId) if err != nil { + ctx.Logger().Error("channel close confirm callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrap(err, "could not retrieve module from port-id")) return nil, sdkerrors.Wrap(err, "could not retrieve module from port-id") } // Retrieve callbacks from router cbs, ok := k.Router.GetRoute(module) if !ok { + ctx.Logger().Error("channel close confirm callback failed", "port-id", msg.PortId, "error", sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module)) return nil, sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module) } if err = cbs.OnChanCloseConfirm(ctx, msg.PortId, msg.ChannelId); err != nil { + ctx.Logger().Error("channel close confirm callback failed", "port-id", msg.PortId, "channel-id", msg.ChannelId, "error", err.Error()) return nil, sdkerrors.Wrapf(err, "channel close confirm callback failed for port ID: %s, channel ID: %s", msg.PortId, msg.ChannelId) } err = k.ChannelKeeper.ChanCloseConfirm(ctx, msg.PortId, msg.ChannelId, cap, msg.ProofInit, msg.ProofHeight) if err != nil { + ctx.Logger().Error("channel handshake close confirm callback failed", "port-id", msg.PortId, "channel-id", msg.ChannelId, "error", err.Error()) return nil, sdkerrors.Wrap(err, "channel handshake close confirm failed") } + ctx.Logger().Info("channel close confirm callback succeeded", "channel-id", msg.ChannelId, "port-id", msg.PortId) + return &channeltypes.MsgChannelCloseConfirmResponse{}, nil } @@ -373,18 +409,21 @@ func (k Keeper) RecvPacket(goCtx context.Context, msg *channeltypes.MsgRecvPacke relayer, err := sdk.AccAddressFromBech32(msg.Signer) if err != nil { + ctx.Logger().Error("receive packet failed", "error", sdkerrors.Wrap(err, "Invalid address for msg Signer")) return nil, sdkerrors.Wrap(err, "Invalid address for msg Signer") } // Lookup module by channel capability module, cap, err := k.ChannelKeeper.LookupModuleByChannel(ctx, msg.Packet.DestinationPort, msg.Packet.DestinationChannel) if err != nil { + ctx.Logger().Error("receive packet failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "could not retrieve module from port-id")) return nil, sdkerrors.Wrap(err, "could not retrieve module from port-id") } // Retrieve callbacks from router cbs, ok := k.Router.GetRoute(module) if !ok { + ctx.Logger().Error("receive packet failed", "port-id", msg.Packet.SourcePort, "error", sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module)) return nil, sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module) } @@ -402,6 +441,7 @@ func (k Keeper) RecvPacket(goCtx context.Context, msg *channeltypes.MsgRecvPacke // no-ops do not need event emission as they will be ignored return &channeltypes.MsgRecvPacketResponse{Result: channeltypes.NOOP}, nil default: + ctx.Logger().Error("receive packet failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "receive packet verification failed")) return nil, sdkerrors.Wrap(err, "receive packet verification failed") } @@ -441,6 +481,8 @@ func (k Keeper) RecvPacket(goCtx context.Context, msg *channeltypes.MsgRecvPacke ) }() + ctx.Logger().Info("receive packet callback succeeded", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "result", channeltypes.SUCCESS.String()) + return &channeltypes.MsgRecvPacketResponse{Result: channeltypes.SUCCESS}, nil } @@ -450,18 +492,21 @@ func (k Keeper) Timeout(goCtx context.Context, msg *channeltypes.MsgTimeout) (*c relayer, err := sdk.AccAddressFromBech32(msg.Signer) if err != nil { + ctx.Logger().Error("timeout failed", "error", sdkerrors.Wrap(err, "Invalid address for msg Signer")) return nil, sdkerrors.Wrap(err, "Invalid address for msg Signer") } // Lookup module by channel capability module, cap, err := k.ChannelKeeper.LookupModuleByChannel(ctx, msg.Packet.SourcePort, msg.Packet.SourceChannel) if err != nil { + ctx.Logger().Error("timeout failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "could not retrieve module from port-id")) return nil, sdkerrors.Wrap(err, "could not retrieve module from port-id") } // Retrieve callbacks from router cbs, ok := k.Router.GetRoute(module) if !ok { + ctx.Logger().Error("timeout failed", "port-id", msg.Packet.SourcePort, "error", sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module)) return nil, sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module) } @@ -479,12 +524,14 @@ func (k Keeper) Timeout(goCtx context.Context, msg *channeltypes.MsgTimeout) (*c // no-ops do not need event emission as they will be ignored return &channeltypes.MsgTimeoutResponse{Result: channeltypes.NOOP}, nil default: + ctx.Logger().Error("timeout failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "timeout packet verification failed")) return nil, sdkerrors.Wrap(err, "timeout packet verification failed") } // Perform application logic callback err = cbs.OnTimeoutPacket(ctx, msg.Packet, relayer) if err != nil { + ctx.Logger().Error("timeout failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "timeout packet callback failed")) return nil, sdkerrors.Wrap(err, "timeout packet callback failed") } @@ -507,6 +554,8 @@ func (k Keeper) Timeout(goCtx context.Context, msg *channeltypes.MsgTimeout) (*c ) }() + ctx.Logger().Info("timeout packet callback succeeded", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "result", channeltypes.SUCCESS.String()) + return &channeltypes.MsgTimeoutResponse{Result: channeltypes.SUCCESS}, nil } @@ -516,18 +565,21 @@ func (k Keeper) TimeoutOnClose(goCtx context.Context, msg *channeltypes.MsgTimeo relayer, err := sdk.AccAddressFromBech32(msg.Signer) if err != nil { + ctx.Logger().Error("timeout on close failed", "error", sdkerrors.Wrap(err, "Invalid address for msg Signer")) return nil, sdkerrors.Wrap(err, "Invalid address for msg Signer") } // Lookup module by channel capability module, cap, err := k.ChannelKeeper.LookupModuleByChannel(ctx, msg.Packet.SourcePort, msg.Packet.SourceChannel) if err != nil { + ctx.Logger().Error("timeout on close failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "could not retrieve module from port-id")) return nil, sdkerrors.Wrap(err, "could not retrieve module from port-id") } // Retrieve callbacks from router cbs, ok := k.Router.GetRoute(module) if !ok { + ctx.Logger().Error("timeout on close failed", "port-id", msg.Packet.SourcePort, "error", sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module)) return nil, sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module) } @@ -545,6 +597,7 @@ func (k Keeper) TimeoutOnClose(goCtx context.Context, msg *channeltypes.MsgTimeo // no-ops do not need event emission as they will be ignored return &channeltypes.MsgTimeoutOnCloseResponse{Result: channeltypes.NOOP}, nil default: + ctx.Logger().Error("timeout on close failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "timeout on close packet verification failed")) return nil, sdkerrors.Wrap(err, "timeout on close packet verification failed") } @@ -554,6 +607,7 @@ func (k Keeper) TimeoutOnClose(goCtx context.Context, msg *channeltypes.MsgTimeo // application logic callback. err = cbs.OnTimeoutPacket(ctx, msg.Packet, relayer) if err != nil { + ctx.Logger().Error("timeout on close failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "timeout packet callback failed")) return nil, sdkerrors.Wrap(err, "timeout packet callback failed") } @@ -576,6 +630,8 @@ func (k Keeper) TimeoutOnClose(goCtx context.Context, msg *channeltypes.MsgTimeo ) }() + ctx.Logger().Info("timeout on close callback succeeded", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "result", channeltypes.SUCCESS.String()) + return &channeltypes.MsgTimeoutOnCloseResponse{Result: channeltypes.SUCCESS}, nil } @@ -585,18 +641,21 @@ func (k Keeper) Acknowledgement(goCtx context.Context, msg *channeltypes.MsgAckn relayer, err := sdk.AccAddressFromBech32(msg.Signer) if err != nil { + ctx.Logger().Error("acknowledgement failed", "error", sdkerrors.Wrap(err, "Invalid address for msg Signer")) return nil, sdkerrors.Wrap(err, "Invalid address for msg Signer") } // Lookup module by channel capability module, cap, err := k.ChannelKeeper.LookupModuleByChannel(ctx, msg.Packet.SourcePort, msg.Packet.SourceChannel) if err != nil { + ctx.Logger().Error("acknowledgement failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "could not retrieve module from port-id")) return nil, sdkerrors.Wrap(err, "could not retrieve module from port-id") } // Retrieve callbacks from router cbs, ok := k.Router.GetRoute(module) if !ok { + ctx.Logger().Error("acknowledgement failed", "port-id", msg.Packet.SourcePort, "error", sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module)) return nil, sdkerrors.Wrapf(porttypes.ErrInvalidRoute, "route not found to module: %s", module) } @@ -614,12 +673,14 @@ func (k Keeper) Acknowledgement(goCtx context.Context, msg *channeltypes.MsgAckn // no-ops do not need event emission as they will be ignored return &channeltypes.MsgAcknowledgementResponse{Result: channeltypes.NOOP}, nil default: + ctx.Logger().Error("acknowledgement failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "acknowledge packet verification failed")) return nil, sdkerrors.Wrap(err, "acknowledge packet verification failed") } // Perform application logic callback err = cbs.OnAcknowledgementPacket(ctx, msg.Packet, msg.Acknowledgement, relayer) if err != nil { + ctx.Logger().Error("acknowledgement failed", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "error", sdkerrors.Wrap(err, "acknowledge packet callback failed")) return nil, sdkerrors.Wrap(err, "acknowledge packet callback failed") } @@ -636,5 +697,7 @@ func (k Keeper) Acknowledgement(goCtx context.Context, msg *channeltypes.MsgAckn ) }() + ctx.Logger().Info("acknowledgement succeeded", "port-id", msg.Packet.SourcePort, "channel-id", msg.Packet.SourceChannel, "result", channeltypes.SUCCESS.String()) + return &channeltypes.MsgAcknowledgementResponse{Result: channeltypes.SUCCESS}, nil }