From b7bab5c401381193d3aafce39317ba5c9aca9da3 Mon Sep 17 00:00:00 2001
From: Joel Zhu <66701969+tianzhu007@users.noreply.github.com>
Date: Tue, 25 Oct 2022 20:21:13 +0000
Subject: [PATCH] Add Logs for SessionHelper (#12574)

We have one session existing in the two clusters at the same time, we
don't have enough telemetry to debug this case. When a client would like
to open an existing session, it might doesn't follow the session
stickiness time, and directly join from the wrong cluster. For example,
one session just terminated in cluster A. After a few minutes, it
violate the session stickiness time (3 hours) and was open in cluster B.
We would like to add more telemetry to debug this scenario.

![Screen Shot 2022-10-18 at 7 23 20
PM](https://user-images.githubusercontent.com/66701969/196582570-a6e0cecd-39b8-42bb-baf9-9465124113c0.png)
---
 .../src/utils/sessionHelper.ts                | 33 ++++++++++++++++---
 1 file changed, 28 insertions(+), 5 deletions(-)

diff --git a/server/routerlicious/packages/routerlicious-base/src/utils/sessionHelper.ts b/server/routerlicious/packages/routerlicious-base/src/utils/sessionHelper.ts
index f27582e3f419..5a640fb4262c 100644
--- a/server/routerlicious/packages/routerlicious-base/src/utils/sessionHelper.ts
+++ b/server/routerlicious/packages/routerlicious-base/src/utils/sessionHelper.ts
@@ -74,12 +74,21 @@ async function updateExistingSession(
     // that ops are backed up to a global location before a session is allowed to move.
     // Otherwise, a moved session could end up without access to ops that still only exist in a location's
     // non-global storage.
+    const sessionStickyCalculationTimestamp = Date.now();
     const isSessionSticky = document.lastAccessTime !== undefined
-        ? Date.now() - document.lastAccessTime < sessionStickinessDurationMs
+        ? sessionStickyCalculationTimestamp - document.lastAccessTime < sessionStickinessDurationMs
         : false; // If no session end has been recorded, allow session to move.
     // Allow session stickiness to be overridden by manually deleting a session's orderer/historian urls.
     const sessionHasLocation: boolean =
         !!existingSession.ordererUrl && !!existingSession.historianUrl && !!existingSession.deltaStreamUrl;
+    Lumberjack.info("Calculated isSessionSticky and sessionHasLocation", {
+        ...lumberjackProperties,
+        isSessionSticky,
+        sessionHasLocation,
+        documentLastAccessTime: document.lastAccessTime,
+        sessionStickyCalculationTimestamp,
+        sessionStickinessDurationMs,
+        });
     if (!isSessionSticky || !sessionHasLocation) {
         // Allow session location to be moved.
         if (
@@ -89,10 +98,14 @@ async function updateExistingSession(
         ) {
             // Previous session was in a different location. Move to current location.
             // Reset logOffset, ordererUrl, and historianUrl when moving session location.
-            Lumberjack.info(
-                `Reset logOffset, ordererUrl, and historianUrl when switching cluster.`,
-                lumberjackProperties,
-            );
+            Lumberjack.info("Moving session", {
+                ...lumberjackProperties,
+                isSessionSticky,
+                sessionHasLocation,
+                // eslint-disable-next-line max-len
+                oldSessionLocation: { ordererUrl: existingSession.ordererUrl, historianUrl: existingSession.historianUrl, deltaStreamUrl: existingSession.deltaStreamUrl },
+                newSessionLocation: { ordererUrl, historianUrl, deltaStreamUrl },
+              });
             updatedOrdererUrl = ordererUrl;
             updatedHistorianUrl = historianUrl;
             updatedDeltaStreamUrl = deltaStreamUrl;
@@ -100,11 +113,13 @@ async function updateExistingSession(
                 const deli = JSON.parse(document.deli);
                 deli.logOffset = -1;
                 updatedDeli = JSON.stringify(deli);
+                Lumberjack.info(`Reset deli logOffset as -1`, lumberjackProperties);
             }
             if (document.scribe !== "") {
                 const scribe = JSON.parse(document.scribe);
                 scribe.logOffset = -1;
                 updatedScribe = JSON.stringify(scribe);
+                Lumberjack.info(`Reset scribe logOffset as -1`, lumberjackProperties);
             }
         }
     }
@@ -129,6 +144,10 @@ async function updateExistingSession(
                 session: updatedSession,
             },
             null);
+        Lumberjack.info(
+            `The Session ${JSON.stringify(updatedSession)} was updated into the document collection`,
+            lumberjackProperties,
+        );
     } catch (error) {
         Lumberjack.error("Error persisting update to existing document session", lumberjackProperties, error);
         throw new NetworkError(500, "Failed to persist update to document session");
@@ -176,6 +195,10 @@ export async function getSession(
     }
     // Session can be undefined for documents that existed before the concept of service sessions.
     const existingSession: ISession | undefined = document.session;
+    Lumberjack.info(
+        `The existingSession in getSession: ${JSON.stringify(existingSession)}`,
+        lumberjackProperties,
+    );
 
     if (!existingSession) {
         // Create a new session for the document and persist to DB.