From 46115fafd50c4126f63c9a61e30c8ac3cbeb84e7 Mon Sep 17 00:00:00 2001 From: Tulir Asokan Date: Sun, 12 Mar 2023 14:25:24 +0200 Subject: [PATCH] Switch user and puppet files to zerolog --- custompuppet.go | 12 ++- discord.go | 19 +++-- puppet.go | 19 +++-- thread.go | 5 +- user.go | 204 +++++++++++++++++++++++++++++------------------- 5 files changed, 156 insertions(+), 103 deletions(-) diff --git a/custompuppet.go b/custompuppet.go index fcf1770..f6b5659 100644 --- a/custompuppet.go +++ b/custompuppet.go @@ -112,13 +112,17 @@ func (puppet *Puppet) tryRelogin(cause error, action string) bool { if !puppet.bridge.Config.CanAutoDoublePuppet(puppet.CustomMXID) { return false } - puppet.log.Debugfln("Trying to relogin after '%v' while %s", cause, action) + log := puppet.log.With(). + AnErr("cause_error", cause). + Str("while_action", action). + Logger() + log.Debug().Msg("Trying to relogin") accessToken, err := puppet.loginWithSharedSecret(puppet.CustomMXID) if err != nil { - puppet.log.Errorfln("Failed to relogin after '%v' while %s: %v", cause, action, err) + log.Error().Err(err).Msg("Failed to relogin") return false } - puppet.log.Infofln("Successfully relogined after '%v' while %s", cause, action) + log.Info().Msg("Successfully relogined") puppet.AccessToken = accessToken puppet.Update() return true @@ -126,7 +130,7 @@ func (puppet *Puppet) tryRelogin(cause error, action string) bool { func (puppet *Puppet) loginWithSharedSecret(mxid id.UserID) (string, error) { _, homeserver, _ := mxid.Parse() - puppet.log.Debugfln("Logging into %s with shared secret", mxid) + puppet.log.Debug().Str("user_id", mxid.String()).Msg("Logging into double puppet target with shared secret") loginSecret := puppet.bridge.Config.Bridge.LoginSharedSecretMap[homeserver] client, err := puppet.bridge.newDoublePuppetClient(mxid, "") if err != nil { diff --git a/discord.go b/discord.go index f8c74fb..37cddbc 100644 --- a/discord.go +++ b/discord.go @@ -18,30 +18,35 @@ func (user *User) channelIsBridgeable(channel *discordgo.Channel) bool { return false } + log := user.log.With().Str("guild_id", channel.GuildID).Str("channel_id", channel.ID).Logger() + member, err := user.Session.State.Member(channel.GuildID, user.DiscordID) if errors.Is(err, discordgo.ErrStateNotFound) { - user.log.Debugfln("Fetching own membership in %s to check own roles", channel.GuildID) + log.Debug().Msg("Fetching own membership in guild to check roles") member, err = user.Session.GuildMember(channel.GuildID, user.DiscordID) if err != nil { - user.log.Warnfln("Failed to get own membership in %s from server to determine own roles for bridging %s: %v", channel.GuildID, channel.ID, err) + log.Warn().Err(err).Msg("Failed to get own membership in guild from server") } else { err = user.Session.State.MemberAdd(member) if err != nil { - user.log.Warnfln("Failed to add own membership in %s to cache: %v", channel.GuildID, err) + log.Warn().Err(err).Msg("Failed to add own membership in guild to cache") } } } else if err != nil { - user.log.Warnfln("Failed to get own membership in %s from cache to determine own roles for bridging %s: %v", channel.GuildID, channel.ID, err) + log.Warn().Err(err).Msg("Failed to get own membership in guild from cache") } err = user.Session.State.ChannelAdd(channel) if err != nil { - user.log.Warnfln("Failed to add channel %s/%s to cache: %v", channel.GuildID, channel.ID, err) + log.Warn().Err(err).Msg("Failed to add channel to cache") } perms, err := user.Session.State.UserChannelPermissions(user.DiscordID, channel.ID) if err != nil { - user.log.Warnfln("Failed to get permissions in %s/%s to determine if it's bridgeable: %v", channel.GuildID, channel.ID, err) + log.Warn().Err(err).Msg("Failed to get permissions in channel to determine if it's bridgeable") return true } - user.log.Debugfln("Computed permissions in %s/%s: %d (view channel: %t)", channel.GuildID, channel.ID, perms, perms&discordgo.PermissionViewChannel > 0) + log.Debug(). + Int64("permissions", perms). + Bool("view_channel", perms&discordgo.PermissionViewChannel > 0). + Msg("Computed permissions in channel") return perms&discordgo.PermissionViewChannel > 0 } diff --git a/puppet.go b/puppet.go index f790f63..a12db30 100644 --- a/puppet.go +++ b/puppet.go @@ -5,9 +5,8 @@ import ( "regexp" "sync" - log "maunium.net/go/maulogger/v2" - "github.com/bwmarrin/discordgo" + "github.com/rs/zerolog" "maunium.net/go/mautrix/appservice" "maunium.net/go/mautrix/bridge" @@ -20,7 +19,7 @@ type Puppet struct { *database.Puppet bridge *DiscordBridge - log log.Logger + log zerolog.Logger MXID id.UserID @@ -43,7 +42,7 @@ func (br *DiscordBridge) NewPuppet(dbPuppet *database.Puppet) *Puppet { return &Puppet{ Puppet: dbPuppet, bridge: br, - log: br.Log.Sub(fmt.Sprintf("Puppet/%s", dbPuppet.ID)), + log: br.ZLog.With().Str("discord_user_id", dbPuppet.ID).Logger(), MXID: br.FormatPuppetMXID(dbPuppet.ID), } @@ -202,7 +201,7 @@ func (puppet *Puppet) UpdateName(info *discordgo.User) bool { puppet.NameSet = false err := puppet.DefaultIntent().SetDisplayName(newName) if err != nil { - puppet.log.Warnln("Failed to update displayname:", err) + puppet.log.Warn().Err(err).Msg("Failed to update displayname") } else { go puppet.updatePortalMeta(func(portal *Portal) { if portal.UpdateNameDirect(puppet.Name) { @@ -228,7 +227,7 @@ func (puppet *Puppet) UpdateAvatar(info *discordgo.User) bool { if puppet.Avatar != "" && (puppet.AvatarURL.IsEmpty() || avatarChanged) { url, err := uploadAvatar(puppet.DefaultIntent(), info.AvatarURL("")) if err != nil { - puppet.log.Warnfln("Failed to reupload user avatar %s: %v", puppet.Avatar, err) + puppet.log.Warn().Err(err).Str("avatar_id", puppet.Avatar).Msg("Failed to reupload user avatar") return true } puppet.AvatarURL = url @@ -236,7 +235,7 @@ func (puppet *Puppet) UpdateAvatar(info *discordgo.User) bool { err := puppet.DefaultIntent().SetAvatarURL(puppet.AvatarURL) if err != nil { - puppet.log.Warnln("Failed to update avatar:", err) + puppet.log.Warn().Err(err).Msg("Failed to update avatar") } else { go puppet.updatePortalMeta(func(portal *Portal) { if portal.UpdateAvatarFromPuppet(puppet) { @@ -258,17 +257,17 @@ func (puppet *Puppet) UpdateInfo(source *User, info *discordgo.User) { return } var err error - puppet.log.Debugfln("Fetching info through %s to update", source.DiscordID) + puppet.log.Debug().Str("source_user", source.DiscordID).Msg("Fetching info through user to update puppet") info, err = source.Session.User(puppet.ID) if err != nil { - puppet.log.Errorfln("Failed to fetch info through %s: %v", source.DiscordID, err) + puppet.log.Error().Err(err).Str("source_user", source.DiscordID).Msg("Failed to fetch info through user") return } } err := puppet.DefaultIntent().EnsureRegistered() if err != nil { - puppet.log.Errorln("Failed to ensure registered:", err) + puppet.log.Error().Err(err).Msg("Failed to ensure registered") } changed := false diff --git a/thread.go b/thread.go index b775d9f..843beb5 100644 --- a/thread.go +++ b/thread.go @@ -78,7 +78,8 @@ func (thread *Thread) Join(user *User) { if user.IsInPortal(thread.ID) { return } - user.log.Debugfln("Joining thread %s@%s", thread.ID, thread.ParentID) + log := user.log.With().Str("thread_id", thread.ID).Str("channel_id", thread.ParentID).Logger() + log.Debug().Msg("Joining thread") var err error if user.Session.IsUser { err = user.Session.ThreadJoinWithLocation(thread.ID, discordgo.ThreadJoinLocationContextMenu) @@ -86,7 +87,7 @@ func (thread *Thread) Join(user *User) { err = user.Session.ThreadJoin(thread.ID) } if err != nil { - user.log.Errorfln("Error joining thread %s@%s: %v", thread.ID, thread.ParentID, err) + log.Error().Err(err).Msg("Error joining thread") } else { user.MarkInPortal(database.UserPortal{ DiscordID: thread.ID, diff --git a/user.go b/user.go index 7cf00c3..6b300cb 100644 --- a/user.go +++ b/user.go @@ -12,11 +12,9 @@ import ( "sync/atomic" "time" + "github.com/bwmarrin/discordgo" "github.com/gorilla/websocket" "github.com/rs/zerolog" - log "maunium.net/go/maulogger/v2" - - "github.com/bwmarrin/discordgo" "maunium.net/go/mautrix" "maunium.net/go/mautrix/appservice" @@ -41,7 +39,7 @@ type User struct { sync.Mutex bridge *DiscordBridge - log log.Logger + log zerolog.Logger PermissionLevel bridgeconfig.PermissionLevel @@ -184,7 +182,7 @@ func (br *DiscordBridge) NewUser(dbUser *database.User) *User { user := &User{ User: dbUser, bridge: br, - log: br.Log.Sub("User").Sub(string(dbUser.MXID)), + log: br.ZLog.With().Str("user_id", string(dbUser.MXID)).Logger(), markedOpened: make(map[string]time.Time), PermissionLevel: br.Config.Bridge.Permissions.Get(dbUser.MXID), @@ -214,7 +212,7 @@ func (br *DiscordBridge) getAllUsersWithToken() []*User { } func (br *DiscordBridge) startUsers() { - br.Log.Debugln("Starting users") + br.ZLog.Debug().Msg("Starting users") usersWithToken := br.getAllUsersWithToken() for _, u := range usersWithToken { @@ -224,13 +222,13 @@ func (br *DiscordBridge) startUsers() { br.SendGlobalBridgeState(status.BridgeState{StateEvent: status.StateUnconfigured}.Fill(nil)) } - br.Log.Debugln("Starting custom puppets") + br.ZLog.Debug().Msg("Starting custom puppets") for _, customPuppet := range br.GetAllPuppetsWithCustomMXID() { go func(puppet *Puppet) { - br.Log.Debugln("Starting custom puppet", puppet.CustomMXID) + br.ZLog.Debug().Str("user_id", puppet.CustomMXID.String()).Msg("Starting custom puppet") if err := puppet.StartCustomMXID(true); err != nil { - puppet.log.Errorln("Failed to start custom puppet:", err) + puppet.log.Error().Err(err).Msg("Failed to start custom puppet") } }(customPuppet) } @@ -240,14 +238,14 @@ func (user *User) startupTryConnect(retryCount int) { user.BridgeState.Send(status.BridgeState{StateEvent: status.StateConnecting}) err := user.Connect() if err != nil { - user.log.Errorfln("Error connecting: %v", err) + user.log.Error().Err(err).Msg("Error connecting on startup") closeErr := &websocket.CloseError{} if errors.As(err, &closeErr) && closeErr.Code == 4004 { user.invalidAuthHandler(nil, nil) } else if retryCount < 6 { user.BridgeState.Send(status.BridgeState{StateEvent: status.StateTransientDisconnect, Error: "dc-unknown-websocket-error", Message: err.Error()}) retryInSeconds := 2 << retryCount - user.log.Debugfln("Retrying connection in %d seconds", retryInSeconds) + user.log.Debug().Int("retry_in_seconds", retryInSeconds).Msg("Sleeping and retrying connection") time.Sleep(time.Duration(retryInSeconds) * time.Second) user.startupTryConnect(retryCount + 1) } else { @@ -321,7 +319,7 @@ func (user *User) getSpaceRoom(ptr *id.RoomID, name, topic string, parent id.Roo }) if err != nil { - user.log.Errorln("Failed to auto-create space room:", err) + user.log.Error().Err(err).Msg("Failed to auto-create space room") } else { *ptr = resp.RoomID user.Update() @@ -333,7 +331,10 @@ func (user *User) getSpaceRoom(ptr *id.RoomID, name, topic string, parent id.Roo Order: " 0000", }) if err != nil { - user.log.Errorfln("Failed to add space room %s to parent space %s: %v", resp.RoomID, parent, err) + user.log.Error().Err(err). + Str("created_space_id", resp.RoomID.String()). + Str("parent_space_id", parent.String()). + Msg("Failed to add created space room to parent space") } } } @@ -356,30 +357,27 @@ func (user *User) tryAutomaticDoublePuppeting() { return } - user.log.Debugln("Checking if double puppeting needs to be enabled") + user.log.Debug().Msg("Checking if double puppeting needs to be enabled") puppet := user.bridge.GetPuppetByID(user.DiscordID) if puppet.CustomMXID != "" { - user.log.Debugln("User already has double-puppeting enabled") - + user.log.Debug().Msg("User already has double-puppeting enabled") return } accessToken, err := puppet.loginWithSharedSecret(user.MXID) if err != nil { - user.log.Warnln("Failed to login with shared secret:", err) - + user.log.Warn().Err(err).Msg("Failed to login with shared secret") return } err = puppet.SwitchCustomMXID(accessToken, user.MXID) if err != nil { - puppet.log.Warnln("Failed to switch to auto-logined custom puppet:", err) - + puppet.log.Warn().Err(err).Msg("Failed to switch to auto-logined custom puppet") return } - user.log.Infoln("Successfully automatically enabled custom puppet") + user.log.Info().Msg("Successfully automatically enabled custom puppet") } func (user *User) ViewingChannel(portal *Portal) bool { @@ -394,7 +392,9 @@ func (user *User) ViewingChannel(portal *Portal) bool { user.markedOpened[portal.Key.ChannelID] = time.Now() err := user.Session.MarkViewing(portal.Key.ChannelID) if err != nil { - user.log.Errorfln("Failed to mark user as viewing %s: %v", portal.Key.ChannelID, err) + user.log.Error().Err(err). + Str("channel_id", portal.Key.ChannelID). + Msg("Failed to mark user as viewing channel") } return true } @@ -407,16 +407,18 @@ func (user *User) mutePortal(intent *appservice.IntentAPI, portal *Portal, unmut } var err error if unmute { - user.log.Debugfln("Unmuting portal %s", portal.MXID) + user.log.Debug().Str("room_id", portal.MXID.String()).Msg("Unmuting portal") err = intent.DeletePushRule("global", pushrules.RoomRule, string(portal.MXID)) } else { - user.log.Debugfln("Muting portal %s", portal.MXID) + user.log.Debug().Str("room_id", portal.MXID.String()).Msg("Muting portal") err = intent.PutPushRule("global", pushrules.RoomRule, string(portal.MXID), &mautrix.ReqPutPushRule{ Actions: []pushrules.PushActionType{pushrules.ActionDontNotify}, }) } if err != nil && !errors.Is(err, mautrix.MNotFound) { - user.log.Warnfln("Failed to update push rule for %s through double puppet: %v", portal.MXID, err) + user.log.Warn().Err(err). + Str("room_id", portal.MXID.String()). + Msg("Failed to update push rule through double puppet") } } @@ -451,7 +453,7 @@ Loop: user.Update() return nil } - user.log.Errorfln("Error connecting for login: %v", err) + user.log.Error().Err(err).Msg("Error connecting for login") closeErr := &websocket.CloseError{} errors.As(err, &closeErr) switch closeErr.Code { @@ -485,14 +487,14 @@ func (user *User) Logout(isOverwriting bool) { if puppet.CustomMXID != "" { err := puppet.SwitchCustomMXID("", "") if err != nil { - user.log.Warnln("Failed to logout-matrix while logging out of Discord:", err) + user.log.Warn().Err(err).Msg("Failed to disable custom puppet while logging out of Discord") } } } if user.Session != nil { if err := user.Session.Close(); err != nil { - user.log.Warnln("Error closing session:", err) + user.log.Warn().Err(err).Msg("Error closing session") } } @@ -508,7 +510,7 @@ func (user *User) Logout(isOverwriting bool) { } user.DiscordID = "" user.Update() - user.log.Infoln("User logged out") + user.log.Info().Msg("User logged out") } func (user *User) Connected() bool { @@ -544,7 +546,7 @@ func (user *User) Connect() error { return ErrNotLoggedIn } - user.log.Debugln("Connecting to discord") + user.log.Debug().Msg("Connecting to discord") session, err := discordgo.New(user.DiscordToken) if err != nil { @@ -598,7 +600,7 @@ func (user *User) Disconnect() error { return ErrNotConnected } - user.log.Infoln("Disconnecting session manually") + user.log.Info().Msg("Disconnecting session manually") if err := user.Session.Close(); err != nil { return err } @@ -618,7 +620,7 @@ func (user *User) getGuildBridgingMode(guildID string) database.GuildBridgingMod } func (user *User) readyHandler(_ *discordgo.Session, r *discordgo.Ready) { - user.log.Debugln("Discord connection ready") + user.log.Debug().Msg("Discord connection ready") user.bridgeStateLock.Lock() user.wasLoggedOut = false user.bridgeStateLock.Unlock() @@ -627,7 +629,9 @@ func (user *User) readyHandler(_ *discordgo.Session, r *discordgo.Ready) { user.bridge.usersLock.Lock() user.DiscordID = r.User.ID if previousUser, ok := user.bridge.usersByID[user.DiscordID]; ok && previousUser != user { - user.log.Warnfln("Another user (%s) is logged in with same Discord ID, logging them out", previousUser.MXID) + user.log.Warn(). + Str("previous_user_id", previousUser.MXID.String()). + Msg("Another user is logged in with same Discord ID, logging them out") // TODO send notice? previousUser.Logout(true) } @@ -676,7 +680,7 @@ func (user *User) subscribeGuilds(delay time.Duration) { for _, guildMeta := range user.Session.State.Guilds { guild := user.bridge.GetGuildByID(guildMeta.ID, false) if guild != nil && guild.MXID != "" { - user.log.Debugfln("Subscribing to guild %s", guild.ID) + user.log.Debug().Str("guild_id", guild.ID).Msg("Subscribing to guild") dat := discordgo.GuildSubscribeData{ GuildID: guild.ID, Typing: true, @@ -685,7 +689,7 @@ func (user *User) subscribeGuilds(delay time.Duration) { } err := user.Session.SubscribeGuild(dat) if err != nil { - user.log.Warnfln("Failed to subscribe to %s: %v", guild.ID, err) + user.log.Warn().Err(err).Str("guild_id", guild.ID).Msg("Failed to subscribe to guild") } time.Sleep(delay) } @@ -693,7 +697,7 @@ func (user *User) subscribeGuilds(delay time.Duration) { } func (user *User) resumeHandler(_ *discordgo.Session, r *discordgo.Resumed) { - user.log.Debugln("Discord connection resumed") + user.log.Debug().Msg("Discord connection resumed") user.subscribeGuilds(0 * time.Second) } @@ -705,7 +709,9 @@ func (user *User) addPrivateChannelToSpace(portal *Portal) bool { Via: []string{user.bridge.AS.HomeserverDomain}, }) if err != nil { - user.log.Errorfln("Failed to add DM room %s to user DM space: %v", portal.MXID, err) + user.log.Error().Err(err). + Str("room_id", portal.MXID.String()). + Msg("Failed to add DMM room to user DM space") return false } else { return true @@ -716,7 +722,9 @@ func (user *User) handlePrivateChannel(portal *Portal, meta *discordgo.Channel, if create && portal.MXID == "" { err := portal.CreateMatrixRoom(user, meta) if err != nil { - user.log.Errorfln("Failed to create portal for private channel %s in initial sync: %v", portal.Key.ChannelID, err) + user.log.Error().Err(err). + Str("channel_id", portal.Key.ChannelID). + Msg("Failed to create portal for private channel in create handler") } } else { portal.UpdateInfo(user, meta) @@ -735,7 +743,9 @@ func (user *User) addGuildToSpace(guild *Guild, isInSpace bool, timestamp time.T Via: []string{user.bridge.AS.HomeserverDomain}, }) if err != nil { - user.log.Errorfln("Failed to add guild space %s to user space: %v", guild.MXID, err) + user.log.Error().Err(err). + Str("guild_space_id", guild.MXID.String()). + Msg("Failed to add guild space to user space") } else { isInSpace = true } @@ -778,7 +788,7 @@ func (user *User) handleGuildRoles(guildID string, newRoles []*discordgo.Role) { } txn, err := user.bridge.DB.Begin() if err != nil { - user.log.Errorln("Failed to start transaction for guild role sync:", err) + user.log.Error().Err(err).Msg("Failed to start transaction for guild role sync") panic(err) } for _, role := range newRoles { @@ -793,10 +803,10 @@ func (user *User) handleGuildRoles(guildID string, newRoles []*discordgo.Role) { } err = txn.Commit() if err != nil { - user.log.Errorln("Failed to commit guild role sync:", err) + user.log.Error().Err(err).Msg("Failed to commit guild role sync transaction") rollbackErr := txn.Rollback() if rollbackErr != nil { - user.log.Errorln("Failed to rollback errored guild role sync:", rollbackErr) + user.log.Error().Err(rollbackErr).Msg("Failed to rollback errored guild role sync transaction") } panic(err) } @@ -825,7 +835,10 @@ func (user *User) handleGuild(meta *discordgo.Guild, timestamp time.Time, isInSp if guild.BridgingMode >= database.GuildBridgeEverything && portal.MXID == "" && user.channelIsBridgeable(ch) { err := portal.CreateMatrixRoom(user, ch) if err != nil { - user.log.Errorfln("Failed to create portal for guild channel %s/%s in initial sync: %v", guild.ID, ch.ID, err) + user.log.Error().Err(err). + Str("guild_id", guild.ID). + Str("channel_id", ch.ID). + Msg("Failed to create portal for guild channel in guild handler") } } else { portal.UpdateInfo(user, ch) @@ -841,7 +854,7 @@ func (user *User) handleGuild(meta *discordgo.Guild, timestamp time.Time, isInSp func (user *User) connectedHandler(_ *discordgo.Session, _ *discordgo.Connect) { user.bridgeStateLock.Lock() defer user.bridgeStateLock.Unlock() - user.log.Debugln("Connected to Discord") + user.log.Debug().Msg("Connected to Discord") if user.wasDisconnected { user.wasDisconnected = false user.BridgeState.Send(status.BridgeState{StateEvent: status.StateConnected}) @@ -852,10 +865,10 @@ func (user *User) disconnectedHandler(_ *discordgo.Session, _ *discordgo.Disconn user.bridgeStateLock.Lock() defer user.bridgeStateLock.Unlock() if user.wasLoggedOut { - user.log.Debugln("Disconnected from Discord (not updating bridge state as user was just logged out)") + user.log.Debug().Msg("Disconnected from Discord (not updating bridge state as user was just logged out)") return } - user.log.Debugln("Disconnected from Discord") + user.log.Debug().Msg("Disconnected from Discord") user.wasDisconnected = true user.BridgeState.Send(status.BridgeState{StateEvent: status.StateTransientDisconnect, Error: "dc-transient-disconnect", Message: "Temporarily disconnected from Discord, trying to reconnect"}) } @@ -863,44 +876,52 @@ func (user *User) disconnectedHandler(_ *discordgo.Session, _ *discordgo.Disconn func (user *User) invalidAuthHandler(_ *discordgo.Session, _ *discordgo.InvalidAuth) { user.bridgeStateLock.Lock() defer user.bridgeStateLock.Unlock() - user.log.Infoln("Got logged out from Discord due to invalid token") + user.log.Info().Msg("Got logged out from Discord due to invalid token") user.wasLoggedOut = true user.BridgeState.Send(status.BridgeState{StateEvent: status.StateBadCredentials, Error: "dc-websocket-disconnect-4004", Message: "Discord access token is no longer valid, please log in again"}) go user.Logout(false) } func (user *User) guildCreateHandler(_ *discordgo.Session, g *discordgo.GuildCreate) { - user.log.Infofln("Got guild create event for %s (name: %s, unavailable: %t)", g.ID, g.Name, g.Unavailable) + user.log.Info(). + Str("guild_id", g.ID). + Str("name", g.Name). + Bool("unavailable", g.Unavailable). + Msg("Got guild create event") user.handleGuild(g.Guild, time.Now(), false) } func (user *User) guildDeleteHandler(_ *discordgo.Session, g *discordgo.GuildDelete) { - user.log.Infoln("Got guild delete event for", g.ID) + user.log.Info().Str("guild_id", g.ID).Msg("Got guild delete event") user.MarkNotInPortal(g.ID) guild := user.bridge.GetGuildByID(g.ID, false) if guild == nil || guild.MXID == "" { return } if user.bridge.Config.Bridge.DeleteGuildOnLeave && !user.PortalHasOtherUsers(g.ID) { - user.log.Debugfln("No other users in %s, cleaning up all portals", g.ID) + user.log.Debug().Str("guild_id", g.ID).Msg("No other users in guild, cleaning up all portals") err := user.unbridgeGuild(g.ID) if err != nil { - user.log.Warnfln("Failed to unbridge guild that was deleted: %v", err) + user.log.Warn().Err(err).Msg("Failed to unbridge guild that was deleted") } } } func (user *User) guildUpdateHandler(_ *discordgo.Session, g *discordgo.GuildUpdate) { - user.log.Debugln("Got guild update event for", g.ID) + user.log.Debug().Str("guild_id", g.ID).Msg("Got guild update event") user.handleGuild(g.Guild, time.Now(), user.IsInSpace(g.ID)) } func (user *User) channelCreateHandler(_ *discordgo.Session, c *discordgo.ChannelCreate) { if user.getGuildBridgingMode(c.GuildID) < database.GuildBridgeEverything { - user.log.Debugfln("Ignoring channel create event in unbridged guild %s/%s", c.GuildID, c.ID) + user.log.Debug(). + Str("guild_id", c.GuildID).Str("channel_id", c.ID). + Msg("Ignoring channel create event in unbridged guild") return } - user.log.Infofln("Got channel create event for %s/%s", c.GuildID, c.ID) + user.log.Info(). + Str("guild_id", c.GuildID).Str("channel_id", c.ID). + Msg("Got channel create event") portal := user.GetPortalByMeta(c.Channel) if portal.MXID != "" { return @@ -910,30 +931,40 @@ func (user *User) channelCreateHandler(_ *discordgo.Session, c *discordgo.Channe } else if user.channelIsBridgeable(c.Channel) { err := portal.CreateMatrixRoom(user, c.Channel) if err != nil { - user.log.Errorfln("Error creating Matrix room for %s on channel create event: %v", c.ID, err) + user.log.Error().Err(err). + Str("guild_id", c.GuildID).Str("channel_id", c.ID). + Msg("Error creating Matrix room after channel create event") } } else { - user.log.Debugfln("Got channel create event for %s, but it's not bridgeable, ignoring", c.ID) + user.log.Debug(). + Str("guild_id", c.GuildID).Str("channel_id", c.ID). + Msg("Got channel create event, but it's not bridgeable, ignoring") } } func (user *User) channelDeleteHandler(_ *discordgo.Session, c *discordgo.ChannelDelete) { portal := user.GetExistingPortalByID(c.ID) if portal == nil { - user.log.Debugfln("Ignoring delete of unknown channel %s/%s", c.GuildID, c.ID) + user.log.Debug(). + Str("guild_id", c.GuildID).Str("channel_id", c.ID). + Msg("Ignoring channel delete event of unknown channel") return } - user.log.Infofln("Got channel delete event for %s/%s, cleaning up portal", c.GuildID, c.ID) + user.log.Info(). + Str("guild_id", c.GuildID).Str("channel_id", c.ID). + Msg("Got channel delete event, cleaning up portal") portal.Delete() portal.cleanup(!user.bridge.Config.Bridge.DeletePortalOnChannelDelete) if c.GuildID == "" { user.MarkNotInPortal(portal.Key.ChannelID) } - user.log.Debugfln("Completed cleaning up %s/%s", c.GuildID, c.ID) + user.log.Debug(). + Str("guild_id", c.GuildID).Str("channel_id", c.ID). + Msg("Completed cleaning up channel") } func (user *User) channelPinsUpdateHandler(_ *discordgo.Session, c *discordgo.ChannelPinsUpdate) { - user.log.Debugln("channel pins update") + user.log.Debug().Msg("channel pins update") } func (user *User) channelUpdateHandler(_ *discordgo.Session, c *discordgo.ChannelUpdate) { @@ -957,23 +988,25 @@ func (user *User) findPortal(channelID string) (*Portal, *Thread) { if !user.Session.IsUser { channel, _ := user.Session.State.Channel(channelID) if channel == nil { - user.log.Debugfln("Fetching info of unknown channel %s to handle message", channelID) + user.log.Debug().Str("channel_id", channelID).Msg("Fetching info of unknown channel to handle message") var err error channel, err = user.Session.Channel(channelID) if err != nil { - user.log.Warnfln("Failed to get info of unknown channel %s: %v", channelID, err) + user.log.Warn().Err(err).Str("channel_id", channelID).Msg("Failed to get info of unknown channel") } else { - user.log.Debugfln("Got info for channel %s to handle message", channelID) + user.log.Debug().Str("channel_id", channelID).Msg("Got info for channel to handle message") _ = user.Session.State.ChannelAdd(channel) } } if channel != nil && user.channelIsBridgeable(channel) { - user.log.Debugfln("Creating portal and updating info for %s to handle message", channelID) + user.log.Debug().Str("channel_id", channelID).Msg("Creating portal and updating info to handle message") portal = user.GetPortalByMeta(channel) if channel.GuildID == "" { user.handlePrivateChannel(portal, channel, time.Now(), false, false) } else { - user.log.Warnfln("Unexpected unknown guild channel %s/%s", channel.GuildID, channel.ID) + user.log.Warn(). + Str("channel_id", channel.ID).Str("guild_id", channel.GuildID). + Msg("Unexpected unknown guild channel") } return portal, nil } @@ -989,7 +1022,11 @@ func (user *User) pushPortalMessage(msg interface{}, typeName, channelID, guildI portal, thread := user.findPortal(channelID) if portal == nil { - user.log.Debugfln("Dropping %s in unknown channel %s/%s", typeName, guildID, channelID) + user.log.Debug(). + Str("discord_event", typeName). + Str("guild_id", guildID). + Str("channel_id", channelID). + Msg("Dropping event in unknown channel") return } if mode := user.getGuildBridgingMode(portal.GuildID); mode <= database.GuildBridgeNothing || (portal.MXID == "" && mode <= database.GuildBridgeIfPortalExists) { @@ -1058,14 +1095,20 @@ func (user *User) messageAckHandler(_ *discordgo.Session, m *discordgo.MessageAc } msg := user.bridge.DB.Message.GetLastByDiscordID(portal.Key, m.MessageID) if msg == nil { - user.log.Debugfln("Dropping message ack event for unknown message %s/%s", m.ChannelID, m.MessageID) + user.log.Debug(). + Str("channel_id", m.ChannelID).Str("message_id", m.MessageID). + Msg("Dropping message ack event for unknown message") return } err := dp.CustomIntent().SetReadMarkers(portal.MXID, user.makeReadMarkerContent(msg.MXID)) if err != nil { - user.log.Warnfln("Failed to mark %s/%s as read: %v", msg.MXID, msg.DiscordID, err) + user.log.Error().Err(err). + Str("event_id", msg.MXID.String()).Str("message_id", msg.DiscordID). + Msg("Failed to mark event as read") } else { - user.log.Debugfln("Marked %s/%s as read after Discord message ack event", msg.MXID, msg.DiscordID) + user.log.Debug(). + Str("event_id", msg.MXID.String()).Str("message_id", msg.DiscordID). + Msg("Marked event as read after Discord message ack") if user.ReadStateVersion < m.Version { user.ReadStateVersion = m.Version // TODO maybe don't update every time? @@ -1087,9 +1130,9 @@ func (user *User) interactionSuccessHandler(_ *discordgo.Session, s *discordgo.I defer user.pendingInteractionsLock.Unlock() ce, ok := user.pendingInteractions[s.Nonce] if !ok { - user.log.Debugfln("Got interaction success for unknown interaction %s/%s", s.Nonce, s.ID) + user.log.Debug().Str("nonce", s.Nonce).Str("id", s.ID).Msg("Got interaction success for unknown interaction") } else { - user.log.Infofln("Got interaction success for pending interaction %s/%s", s.Nonce, s.ID) + user.log.Debug().Str("nonce", s.Nonce).Str("id", s.ID).Msg("Got interaction success for pending interaction") ce.React("✅") delete(user.pendingInteractions, s.Nonce) } @@ -1121,7 +1164,7 @@ func (user *User) ensureInvited(intent *appservice.IntentAPI, roomID id.RoomID, user.bridge.StateStore.SetMembership(roomID, user.MXID, event.MembershipJoin) ret = true } else if err != nil { - user.log.Warnfln("Failed to invite user to %s: %v", roomID, err) + user.log.Error().Err(err).Str("room_id", roomID.String()).Msg("Failed to invite user to room") } else { ret = true } @@ -1129,7 +1172,7 @@ func (user *User) ensureInvited(intent *appservice.IntentAPI, roomID id.RoomID, if customPuppet != nil && customPuppet.CustomIntent() != nil { err = customPuppet.CustomIntent().EnsureJoined(roomID, appservice.EnsureJoinedParams{IgnoreCache: true}) if err != nil { - user.log.Warnfln("Failed to auto-join %s: %v", roomID, err) + user.log.Warn().Err(err).Str("room_id", roomID.String()).Msg("Failed to auto-join room") ret = false } else { ret = true @@ -1175,7 +1218,7 @@ func (user *User) updateDirectChats(chats map[id.UserID][]id.RoomID) { method = http.MethodPut } - user.log.Debugln("Updating m.direct list on homeserver") + user.log.Debug().Msg("Updating m.direct list on homeserver") var err error if user.bridge.Config.Homeserver.Software == bridgeconfig.SoftwareAsmux { @@ -1191,8 +1234,7 @@ func (user *User) updateDirectChats(chats map[id.UserID][]id.RoomID) { err = intent.GetAccountData(event.AccountDataDirectChats.Type, &existingChats) if err != nil { - user.log.Warnln("Failed to get m.direct list to update it:", err) - + user.log.Warn().Err(err).Msg("Failed to get m.direct event to update it") return } @@ -1210,7 +1252,7 @@ func (user *User) updateDirectChats(chats map[id.UserID][]id.RoomID) { } if err != nil { - user.log.Warnln("Failed to update m.direct list:", err) + user.log.Warn().Err(err).Msg("Failed to update m.direct event") } } @@ -1224,13 +1266,15 @@ func (user *User) bridgeGuild(guildID string, everything bool) error { if err != nil { return err } + log := user.log.With().Str("guild_id", guild.ID).Logger() user.addGuildToSpace(guild, false, time.Now()) for _, ch := range meta.Channels { portal := user.GetPortalByMeta(ch) if (everything && user.channelIsBridgeable(ch)) || ch.Type == discordgo.ChannelTypeGuildCategory { err = portal.CreateMatrixRoom(user, ch) if err != nil { - user.log.Warnfln("Error creating room for guild channel %s: %v", ch.ID, err) + log.Error().Err(err).Str("channel_id", ch.ID). + Msg("Failed to create room for guild channel while bridging guild") } } } @@ -1240,7 +1284,7 @@ func (user *User) bridgeGuild(guildID string, everything bool) error { guild.Update() if user.Session.IsUser { - user.log.Debugfln("Subscribing to guild %s after bridging", guild.ID) + log.Debug().Msg("Subscribing to guild after bridging") err = user.Session.SubscribeGuild(discordgo.GuildSubscribeData{ GuildID: guild.ID, Typing: true, @@ -1248,7 +1292,7 @@ func (user *User) bridgeGuild(guildID string, everything bool) error { Threads: true, }) if err != nil { - user.log.Warnfln("Failed to subscribe to %s: %v", guild.ID, err) + log.Warn().Err(err).Msg("Failed to subscribe to guild") } }