From c4a79437752774f96eea32e6377b092886989f5c Mon Sep 17 00:00:00 2001
From: Tulir Asokan <tulir@maunium.net>
Date: Mon, 17 Jan 2022 10:38:44 +0200
Subject: [PATCH] Add logs to debug read receipts

---
 database/userportal.go | 1 +
 portal.go              | 5 ++++-
 user.go                | 2 ++
 3 files changed, 7 insertions(+), 1 deletion(-)

diff --git a/database/userportal.go b/database/userportal.go
index e463a9a..be339df 100644
--- a/database/userportal.go
+++ b/database/userportal.go
@@ -51,6 +51,7 @@ func (user *User) SetLastReadTS(portal PortalKey, ts time.Time) {
 	if err != nil {
 		user.log.Warnfln("Failed to update last read timestamp: %v", err)
 	} else {
+		user.log.Debugfln("Set last read timestamp of %s in %s to %d", user.MXID, portal.String(), ts.Unix())
 		user.lastReadCache[portal] = ts
 	}
 }
diff --git a/portal.go b/portal.go
index 1eb4c83..30eaf64 100644
--- a/portal.go
+++ b/portal.go
@@ -2421,8 +2421,10 @@ func (portal *Portal) HandleMatrixReadReceipt(sender *User, eventID id.EventID,
 	}
 
 	prevTimestamp := sender.GetLastReadTS(portal.Key)
+	lastReadIsZero := false
 	if prevTimestamp.IsZero() {
 		prevTimestamp = maxTimestamp.Add(-2 * time.Second)
+		lastReadIsZero = true
 	}
 
 	messages := portal.bridge.DB.Message.GetMessagesBetween(portal.Key, prevTimestamp, maxTimestamp)
@@ -2442,7 +2444,8 @@ func (portal *Portal) HandleMatrixReadReceipt(sender *User, eventID id.EventID,
 		} // else: blank key (participant field isn't needed in direct chat read receipts)
 		groupedMessages[key] = append(groupedMessages[key], msg.JID)
 	}
-	portal.log.Debugfln("Sending read receipts by %s: %v", sender.JID, groupedMessages)
+	portal.log.Debugfln("Sending read receipts by %s (last read: %d, was zero: %t): %v",
+		sender.JID, prevTimestamp.Unix(), lastReadIsZero, groupedMessages)
 	for messageSender, ids := range groupedMessages {
 		chatJID := portal.Key.JID
 		if messageSender.Server == types.BroadcastServer {
diff --git a/user.go b/user.go
index a4353c8..1864e11 100644
--- a/user.go
+++ b/user.go
@@ -897,6 +897,8 @@ func (user *User) markSelfReadFull(portal *Portal) {
 	err := puppet.CustomIntent().MarkReadWithContent(portal.MXID, lastMessage.MXID, &CustomReadReceipt{DoublePuppetSource: doublePuppetValue})
 	if err != nil {
 		user.log.Warnfln("Failed to mark %s (last message) in %s as read: %v", lastMessage.MXID, portal.MXID, err)
+	} else {
+		user.log.Debugfln("Marked %s (last message) in %s as read", lastMessage.MXID, portal.MXID)
 	}
 }