git » sdk » commit 07b57a1

Add server timestamp to debug

author Eric Roberts
2026-09-21 17:37:18 UTC
committer Stephen Paul Weber
2026-09-21 17:43:05 UTC
parent 2e07f893423ee7eb80d897f574f843c07d1293a3
Add server timestamp to debug

As we're trying to debug out of order messages, sometimes they are
expected, like when a message was sent from an unconnected device and
not received by the server until later.

Logging the time we receive things at the server will help differentiate
these cases from actual problematic sorting cases.

I could have just used timestamp instead of making a final
serverReceivedAt but it seemed more clear to me to use that name. Maybe
I should change all the timestamp references but thought maybe that
would be too broad. Happy to change it one way or the other if there's
strong feelings about it.
borogove/Importer.hx +3 -1
borogove/MessageSync.hx +5 -1
test/TestImporter.hx +3 -1
test/TestSortId.hx +2 -0 
diff --git a/borogove/Importer.hx b/borogove/Importer.hx
index 1919e9c..f3961e8 100644
--- a/borogove/Importer.hx
+++ b/borogove/Importer.hx
@@ -145,7 +145,8 @@ class Importer {
 
 		final sortLower = sortA;
 		sortA = FractionalIndexing.between(sortLower, sortB, FractionalIndexing.BASE_95_DIGITS);
-		var timestamp = resultStanza.findText("{urn:xmpp:forward:0}forwarded/{urn:xmpp:delay}delay@stamp");
+		final serverReceivedAt = resultStanza.findText("{urn:xmpp:forward:0}forwarded/{urn:xmpp:delay}delay@stamp");
+		var timestamp = serverReceivedAt;
 		if (timestamp != null) {
 			// If no subseconds, fix them to at least sort right
 			timestamp = ~/([0-9][0-9]:[0-9][0-9]:[0-9][0-9])(\.[0-9][0-9][0-9])?/.map(timestamp, (ereg) -> {
@@ -173,6 +174,7 @@ class Importer {
 			builder.sortId = sortA;
 			builder.debug = {
 				source: "import",
+				serverReceivedAt: serverReceivedAt,
 				sortId: { method: "between", lower: sortLower, upper: sortB },
 			};
 			builder.serverId = resultStanza.attr.get("id");
diff --git a/borogove/MessageSync.hx b/borogove/MessageSync.hx
index 32ea58c..f2596b4 100644
--- a/borogove/MessageSync.hx
+++ b/borogove/MessageSync.hx
@@ -85,7 +85,8 @@ class MessageSync {
 			}
 			final sortLower = sortA;
 			sortA = FractionalIndexing.between(sortLower, sortB, FractionalIndexing.BASE_95_DIGITS);
-			var timestamp = result.findText("{urn:xmpp:forward:0}forwarded/{urn:xmpp:delay}delay@stamp");
+			final serverReceivedAt = result.findText("{urn:xmpp:forward:0}forwarded/{urn:xmpp:delay}delay@stamp");
+			var timestamp = serverReceivedAt;
 			if (timestamp == null) {
 				trace("MAM result with no timestamp", result);
 			} else {
@@ -123,6 +124,7 @@ class MessageSync {
 						builder.sortId = sortId;
 						builder.debug = {
 							source: "mam",
+							serverReceivedAt: serverReceivedAt,
 							serviceJID: serviceJID,
 							filter: filter,
 							path: "decrypted",
@@ -140,6 +142,7 @@ class MessageSync {
 							builder.sortId = sortA;
 							builder.debug = {
 								source: "mam",
+								serverReceivedAt: serverReceivedAt,
 								serviceJID: serviceJID,
 								filter: filter,
 								path: "decryption failed",
@@ -163,6 +166,7 @@ class MessageSync {
 				builder.sortId = sortId;
 				builder.debug = {
 					source: "mam",
+					serverReceivedAt: serverReceivedAt,
 					serviceJID: serviceJID,
 					filter: filter,
 					path: "unencrypted",
diff --git a/test/TestImporter.hx b/test/TestImporter.hx
index dfcba90..c876b79 100644
--- a/test/TestImporter.hx
+++ b/test/TestImporter.hx
@@ -64,6 +64,7 @@ class TestImporter extends utest.Test {
 		i.write("<forwarded xmlns='urn:xmpp:forward:0'>");
 		i.write("<delay xmlns='urn:xmpp:delay' stamp='2023-10-27T10:00:00Z' />");
 		i.write("<message xmlns='jabber:client' from='juliet@capulet.com/balcony' to='romeo@montague.net' id='msg-id-1'>");
+		i.write("<delay xmlns='urn:xmpp:delay' stamp='2023-10-26T09:00:00Z' />");
 		i.write("<body>Hello Romeo</body>");
 		i.write("</message>");
 		i.write("</forwarded>");
@@ -82,7 +83,8 @@ class TestImporter extends utest.Test {
 				Assert.equals("Hello Romeo", chatMsg.body().toPlainText());
 				Assert.equals("mam-id-1", chatMsg.serverId);
 				Assert.equals("juliet@capulet.com", chatMsg.serverIdBy);
-				Assert.equals("2023-10-27T10:00:00.001Z", chatMsg.timestamp);
+				Assert.equals("2023-10-26T09:00:00Z", chatMsg.timestamp);
+				Assert.equals("2023-10-27T10:00:00Z", chatMsg.debug.serverReceivedAt);
 				Assert.equals("import", chatMsg.debug.source);
 				Assert.isFalse(chatMsg.isIncoming());
 			default:
diff --git a/test/TestSortId.hx b/test/TestSortId.hx
index f7df325..9f016d1 100644
--- a/test/TestSortId.hx
+++ b/test/TestSortId.hx
@@ -144,6 +144,8 @@ class TestSortId extends utest.Test {
 			Assert.isTrue(m2.sortId < "b00", "m2.sortId < \"b00\"");
 			Assert.isTrue(m1.timestamp < m2.timestamp, "m1.timestamp < m2.timestamp"); // fake fractional part
 			Assert.equals("mam", m1.debug.source);
+			Assert.equals("2023-01-01T00:00:00Z", m1.debug.serverReceivedAt);
+			Assert.equals("2023-01-01T00:00:00Z", m2.debug.serverReceivedAt);
 			Assert.equals("test@example.com", m1.debug.serviceJID);
 			Assert.equals("mam", m2.debug.source);
 			Assert.equals("between", m1.debug.sortId.method);