Stop using maulogger in Portal

commands.go

@@ -294,29 +294,6 @@ func fnPing(ce *WrappedCommandEvent) {
 	}
 }
 
-func canDeletePortal(portal *Portal, userID id.UserID) bool {
-	if len(portal.MXID) == 0 {
-		return false
-	}
-
-	members, err := portal.MainIntent().JoinedMembers(portal.MXID)
-	if err != nil {
-		portal.log.Errorfln("Failed to get joined members to check if portal can be deleted by %s: %v", userID, err)
-		return false
-	}
-	for otherUser := range members.Joined {
-		_, isPuppet := portal.bridge.ParsePuppetMXID(otherUser)
-		if isPuppet || otherUser == portal.bridge.Bot.UserID || otherUser == userID {
-			continue
-		}
-		user := portal.bridge.GetUserByMXID(otherUser)
-		if user != nil && user.Session != nil {
-			return false
-		}
-	}
-	return true
-}
-
 var cmdDeletePortal = &commands.FullHandler{
 	Func: wrapCommand(fnDeletePortal),
 	Name: "delete-portal",
@@ -328,12 +305,12 @@ var cmdDeletePortal = &commands.FullHandler{
 }
 
 func fnDeletePortal(ce *WrappedCommandEvent) {
-	if !ce.User.Admin && !canDeletePortal(ce.Portal, ce.User.MXID) {
+	if !ce.User.Admin && ce.Portal.Receiver != ce.User.RowID {
-		ce.Reply("Only bridge admins can delete portals with other Matrix users")
+		ce.Reply("Only bridge admins can delete other users' portals")
 		return
 	}
 
-	ce.Portal.log.Infoln(ce.User.MXID, "requested deletion of portal.")
+	ce.ZLog.Info().Str("conversation_id", ce.Portal.ID).Msg("Deleting portal from command")
 	ce.Portal.Delete()
 	ce.Portal.Cleanup(false)
 }

messagetracking.go

@@ -24,8 +24,7 @@ import (
 	"sync"
 	"time"
 
-	log "maunium.net/go/maulogger/v2"
+	"github.com/rs/zerolog"
-
 	"maunium.net/go/mautrix"
 	"maunium.net/go/mautrix/bridge/status"
 	"maunium.net/go/mautrix/event"
@@ -110,7 +109,7 @@ func (portal *Portal) sendErrorMessage(evt *event.Event, err error, msgType stri
 	}
 	resp, err := portal.sendMainIntentMessage(content)
 	if err != nil {
-		portal.log.Warnfln("Failed to send bridging error message:", err)
+		portal.zlog.Warn().Err(err).Str("event_id", evt.ID.String()).Msg("Failed to send bridging error message")
 		return ""
 	}
 	return resp.EventID
@@ -144,7 +143,7 @@ func (portal *Portal) sendStatusEvent(evtID, lastRetry id.EventID, err error) {
 	}
 	_, err = intent.SendMessageEvent(portal.MXID, event.BeeperMessageStatus, &content)
 	if err != nil {
-		portal.log.Warnln("Failed to send message status event:", err)
+		portal.zlog.Warn().Err(err).Str("event_id", evtID.String()).Msg("Failed to send message status event")
 	}
 }
 
@@ -152,7 +151,7 @@ func (portal *Portal) sendDeliveryReceipt(eventID id.EventID) {
 	if portal.bridge.Config.Bridge.DeliveryReceipts {
 		err := portal.bridge.Bot.SendReceipt(portal.MXID, eventID, event.ReceiptTypeRead, nil)
 		if err != nil {
-			portal.log.Debugfln("Failed to send delivery receipt for %s: %v", eventID, err)
+			portal.zlog.Warn().Err(err).Str("event_id", eventID.String()).Msg("Failed to send delivery receipt")
 		}
 	}
 }
@@ -169,20 +168,21 @@ func (portal *Portal) sendMessageMetrics(evt *event.Event, err error, part strin
 	default:
 		msgType = "unknown event"
 	}
-	evtDescription := evt.ID.String()
-	if evt.Type == event.EventRedaction {
-		evtDescription += fmt.Sprintf(" of %s", evt.Redacts)
-	}
 	origEvtID := evt.ID
 	if retryMeta := evt.Content.AsMessage().MessageSendRetry; retryMeta != nil {
 		origEvtID = retryMeta.OriginalEventID
 	}
 	if err != nil {
-		level := log.LevelError
+		logEvt := portal.zlog.Error()
 		if part == "Ignoring" {
-			level = log.LevelDebug
+			logEvt = portal.zlog.Debug()
 		}
-		portal.log.Logfln(level, "%s %s %s from %s: %v", part, msgType, evtDescription, evt.Sender, err)
+		logEvt.Err(err).
+			Str("event_id", evt.ID.String()).
+			Str("part", part).
+			Str("event_sender", evt.Sender.String()).
+			Str("event_type", evt.Type.Type).
+			Msg("Failed to handle Matrix event")
 		reason, statusCode, isCertain, sendNotice, _ := errorToStatusReason(err)
 		checkpointStatus := status.ReasonToCheckpointStatus(reason, statusCode)
 		portal.bridge.SendMessageCheckpoint(evt, status.MsgStepRemote, err, checkpointStatus, ms.getRetryNum())
@@ -191,7 +191,10 @@ func (portal *Portal) sendMessageMetrics(evt *event.Event, err error, part strin
 		}
 		portal.sendStatusEvent(origEvtID, evt.ID, err)
 	} else {
-		portal.log.Debugfln("Handled Matrix %s %s", msgType, evtDescription)
+		portal.zlog.Debug().
+			Str("event_id", evt.ID.String()).
+			Str("event_type", evt.Type.Type).
+			Msg("Handled Matrix event")
 		portal.sendDeliveryReceipt(evt.ID)
 		portal.bridge.SendMessageSuccessCheckpoint(evt, status.MsgStepRemote, ms.getRetryNum())
 		if msgType != "message" {
@@ -204,43 +207,27 @@ func (portal *Portal) sendMessageMetrics(evt *event.Event, err error, part strin
 		}
 	}
 	if ms != nil {
-		portal.log.Debugfln("Timings for %s: %s", evt.ID, ms.timings.String())
+		portal.zlog.Debug().EmbedObject(ms.timings).Str("event_id", evt.ID.String()).Msg("Timings for Matrix event")
 	}
 }
 
 type messageTimings struct {
 	initReceive  time.Duration
 	decrypt      time.Duration
-	implicitRR   time.Duration
 	portalQueue  time.Duration
 	totalReceive time.Duration
 
-	preproc   time.Duration
 	convert time.Duration
-	totalSend time.Duration
+	send    time.Duration
 }
 
-func niceRound(dur time.Duration) time.Duration {
+func (mt *messageTimings) MarshalZerologObject(evt *zerolog.Event) {
-	switch {
+	evt.Dur("receive", mt.initReceive).
-	case dur < time.Millisecond:
+		Dur("decrypt", mt.decrypt).
-		return dur
+		Dur("queue", mt.portalQueue).
-	case dur < time.Second:
+		Dur("total_hs_to_portal", mt.totalReceive).
-		return dur.Round(100 * time.Microsecond)
+		Dur("convert", mt.convert).
-	default:
+		Dur("send", mt.send)
-		return dur.Round(time.Millisecond)
-	}
-}
-
-func (mt *messageTimings) String() string {
-	mt.initReceive = niceRound(mt.initReceive)
-	mt.decrypt = niceRound(mt.decrypt)
-	mt.portalQueue = niceRound(mt.portalQueue)
-	mt.totalReceive = niceRound(mt.totalReceive)
-	mt.implicitRR = niceRound(mt.implicitRR)
-	mt.preproc = niceRound(mt.preproc)
-	mt.convert = niceRound(mt.convert)
-	mt.totalSend = niceRound(mt.totalSend)
-	return fmt.Sprintf("BRIDGE: receive: %s, decrypt: %s, queue: %s, total hs->portal: %s, implicit rr: %s -- PORTAL: preprocess: %s, convert: %s, total send: %s", mt.initReceive, mt.decrypt, mt.implicitRR, mt.portalQueue, mt.totalReceive, mt.preproc, mt.convert, mt.totalSend)
 }
 
 type metricSender struct {

portal.go

@@ -29,7 +29,6 @@ import (
 
 	"github.com/gabriel-vasile/mimetype"
 	"github.com/rs/zerolog"
-	"maunium.net/go/maulogger/v2"
 	mutil "maunium.net/go/mautrix/util"
 	"maunium.net/go/mautrix/util/variationselector"
 
@@ -187,7 +186,6 @@ func (portal *Portal) GetUsers() []*User {
 func (br *GMBridge) newBlankPortal(key database.Key) *Portal {
 	portal := &Portal{
 		bridge: br,
-		log:    br.Log.Sub(fmt.Sprintf("Portal/%s", key.ID)),
 		zlog:   br.ZLog.With().Str("portal_id", key.ID).Int("portal_receiver", key.Receiver).Logger(),
 
 		messages:       make(chan PortalMessage, br.Config.Bridge.PortalMessageBuffer),
@@ -228,8 +226,6 @@ type Portal struct {
 	*database.Portal
 
 	bridge *GMBridge
-	// Deprecated: use zerolog
-	log  maulogger.Logger
 	zlog   zerolog.Logger
 
 	roomCreateLock sync.Mutex
@@ -1059,7 +1055,7 @@ func (portal *Portal) CreateMatrixRoom(user *User, conv *gmproto.Conversation) e
 			if portal.bridge.Config.Bridge.Encryption.Default {
 				err = portal.bridge.Bot.EnsureJoined(portal.MXID)
 				if err != nil {
-					portal.log.Errorln("Failed to join created portal with bridge bot for e2be:", err)
+					portal.zlog.Err(err).Msg("Failed to join created portal with bridge bot for e2be")
 				}
 			}
 
@@ -1312,9 +1308,17 @@ func (portal *Portal) HandleMatrixMessage(sender *User, evt *event.Event, timing
 		content.MsgType = event.MsgImage
 	}
 
-	if req, err := portal.convertMatrixMessage(ctx, sender, content, txnID); err != nil {
+	start := time.Now()
+	req, err := portal.convertMatrixMessage(ctx, sender, content, txnID)
+	timings.convert = time.Since(start)
+	if err != nil {
 		go ms.sendMessageMetrics(evt, err, "Error converting", true)
-	} else if _, err = sender.Client.SendMessage(req); err != nil {
+		return
+	}
+	start = time.Now()
+	_, err = sender.Client.SendMessage(req)
+	timings.send = time.Since(start)
+	if err != nil {
 		go ms.sendMessageMetrics(evt, err, "Error sending", true)
 	} else {
 		go ms.sendMessageMetrics(evt, nil, "", true)
@@ -1529,12 +1533,12 @@ func (portal *Portal) GetMatrixUsers() ([]id.UserID, error) {
 func (portal *Portal) CleanupIfEmpty() {
 	users, err := portal.GetMatrixUsers()
 	if err != nil {
-		portal.log.Errorfln("Failed to get Matrix user list to determine if portal needs to be cleaned up: %v", err)
+		portal.zlog.Err(err).Msg("Failed to get Matrix user list to determine if portal needs to be cleaned up")
 		return
 	}
 
 	if len(users) == 0 {
-		portal.log.Infoln("Room seems to be empty, cleaning up...")
+		portal.zlog.Info().Msg("Room seems to be empty, cleaning up...")
 		portal.Delete()
 		portal.Cleanup(false)
 	}
@@ -1554,7 +1558,7 @@ func (portal *Portal) Cleanup(puppetsOnly bool) {
 	}
 	members, err := intent.JoinedMembers(portal.MXID)
 	if err != nil {
-		portal.log.Errorln("Failed to get portal members for cleanup:", err)
+		portal.zlog.Err(err).Msg("Failed to get portal members for cleanup")
 		return
 	}
 	for member := range members.Joined {
@@ -1565,17 +1569,17 @@ func (portal *Portal) Cleanup(puppetsOnly bool) {
 		if puppet != nil {
 			_, err = puppet.DefaultIntent().LeaveRoom(portal.MXID)
 			if err != nil {
-				portal.log.Errorln("Error leaving as puppet while cleaning up portal:", err)
+				portal.zlog.Err(err).Msg("Failed to leave as puppet while cleaning up portal")
 			}
 		} else if !puppetsOnly {
 			_, err = intent.KickUser(portal.MXID, &mautrix.ReqKickUser{UserID: member, Reason: "Deleting portal"})
 			if err != nil {
-				portal.log.Errorln("Error kicking user while cleaning up portal:", err)
+				portal.zlog.Err(err).Msg("Failed to kick user while cleaning up portal")
 			}
 		}
 	}
 	_, err = intent.LeaveRoom(portal.MXID)
 	if err != nil {
-		portal.log.Errorln("Error leaving with main intent while cleaning up portal:", err)
+		portal.zlog.Err(err).Msg("Failed to leave with main intent while cleaning up portal")
 	}
 }