🐛 fix logs not being sent long after session expiration (#4839)

Author: thomas-lebeau

packages/browser-core/src/domain/session/sessionManager.spec.ts

@@ -799,6 +799,18 @@ describe('startSessionManager', () => {
       expect(sessionManager.findTrackedSession()).toBeUndefined()
     })
 
+    it('should return the session older than TRACKED_SESSION_MAX_AGE when a larger maxAge is provided', async () => {
+      const sessionManager = await startSessionManagerWithDefaults()
+
+      // Let the session expire from inactivity, then age well past TRACKED_SESSION_MAX_AGE. The
+      // in-memory session context entry is kept (bounded by maxEntries, not elapsed time), so it
+      // can still be returned with `returnInactive: true` regardless of how old it is.
+      clock.tick(TRACKED_SESSION_MAX_AGE + ONE_SECOND)
+
+      expect(sessionManager.findTrackedSession(undefined, { returnInactive: true })).toBeUndefined()
+      expect(sessionManager.findTrackedSession(undefined, { returnInactive: true, maxAge: Infinity })).toBeDefined()
+    })
+
     describe('deterministic sampling', () => {
       it('should track a session whose ID has a low hash, even with a low sessionSampleRate', async () => {
         setupFakeStrategy({

packages/browser-core/src/domain/session/sessionManager.ts

@@ -23,7 +23,6 @@ import { display } from '../../tools/display'
 import { isSampled } from '../sampler'
 import { TelemetryMetrics, addTelemetryMetrics } from '../telemetry'
 import { monitorError } from '../../tools/monitor'
-import { SESSION_TIME_OUT_DELAY } from './sessionConstants'
 import type { SessionState } from './sessionState'
 import {
   expandOnly,
@@ -38,7 +37,10 @@ import { getSessionStoreStrategy, selectSessionStoreStrategyType } from './sessi
 
 export interface SessionManager {
   findSession: (startTime?: RelativeTime, options?: { returnInactive: boolean }) => SessionContext | undefined
-  findTrackedSession: (startTime?: RelativeTime, options?: { returnInactive: boolean }) => SessionContext | undefined
+  findTrackedSession: (
+    startTime?: RelativeTime,
+    options?: { returnInactive?: boolean; maxAge?: number }
+  ) => SessionContext | undefined
   renewObservable: Observable<void>
   expireObservable: Observable<void>
   expire: () => void
@@ -53,7 +55,12 @@ export interface SessionContext {
 }
 
 export const VISIBILITY_CHECK_DELAY = ONE_MINUTE
-const SESSION_CONTEXT_TIMEOUT_DELAY = SESSION_TIME_OUT_DELAY
+
+// Arbitrary value to cap memory consumption for very long-lived pages with many session
+// renewals. Entries are *not* evicted based on elapsed time: an idle session's sole (closed)
+// entry must survive indefinitely so browser-logs can keep sending logs after it expires, with
+// or without a session attached (see browser-logs/src/domain/contexts/sessionContext.ts).
+export const MAX_SESSION_CONTEXT_HISTORY_ENTRIES = 1000
 
 // Maximum duration for which we can send data related to a session.
 //
@@ -84,7 +91,7 @@ export async function startSessionManager(
   const strategy = mockable(getSessionStoreStrategy)(sessionStoreStrategyType, configuration)
 
   const sessionContextHistory = createValueHistory<SessionContext>({
-    expireDelay: SESSION_CONTEXT_TIMEOUT_DELAY,
+    maxEntries: MAX_SESSION_CONTEXT_HISTORY_ENTRIES,
   })
   stopCallbacks.push(() => sessionContextHistory.stop())
 
@@ -216,14 +223,14 @@ export async function startSessionManager(
   function buildSessionManager(): SessionManager {
     return {
       findSession: (startTime, options) => sessionContextHistory.find(startTime, options),
-      findTrackedSession: (startTime, options) => {
-        const session = sessionContextHistory.find(startTime, options)
+      findTrackedSession: (startTime, { returnInactive = false, maxAge = TRACKED_SESSION_MAX_AGE } = {}) => {
+        const session = sessionContextHistory.find(startTime, { returnInactive })
 
         if (!session || session.id === 'invalid' || !isSampled(session.id, configuration.sessionSampleRate)) {
           return
         }
 
-        if (dateNow() - session.createdAt > TRACKED_SESSION_MAX_AGE) {
+        if (dateNow() - session.createdAt > maxAge) {
           return
         }
 

packages/browser-core/src/index.ts

@@ -51,6 +51,7 @@ export type { SessionManager, SessionContext } from './domain/session/sessionMan
 export { startSessionManager, startSessionManagerStub, stopSessionManager } from './domain/session/sessionManager'
 export {
   SESSION_TIME_OUT_DELAY, // Exposed for tests
+  SESSION_EXPIRATION_DELAY,
   SESSION_NOT_TRACKED,
   SessionPersistence,
 } from './domain/session/sessionConstants'

packages/browser-core/src/tools/valueHistory.spec.ts

@@ -220,6 +220,18 @@ describe('valueHistory', () => {
       valueHistory1.stop()
       valueHistory2.stop()
     })
+
+    it('should not clear closed entries based on elapsed time when expireDelay is not set', () => {
+      const maxEntriesOnlyHistory = createValueHistory<string>({ maxEntries: MAX_ENTRIES })
+      const originalTime = performance.now() as RelativeTime
+      maxEntriesOnlyHistory.add('foo', originalTime).close(addDuration(originalTime, 10 as Duration))
+
+      clock.tick(EXPIRE_DELAY + CLEAR_OLD_VALUES_INTERVAL)
+
+      expect(maxEntriesOnlyHistory.find(originalTime, { returnInactive: true })).toBeDefined()
+
+      maxEntriesOnlyHistory.stop()
+    })
   })
 
   it('should limit the number of entries', () => {

packages/browser-core/src/tools/valueHistory.ts

@@ -40,27 +40,35 @@ function cleanupHistories() {
   cleanupTasks.forEach((task) => task())
 }
 
-export function createValueHistory<Value>({
-  expireDelay,
-  maxEntries,
-}: {
-  expireDelay: number
-  maxEntries?: number
-}): ValueHistory<Value> {
-  let entries: Array<ValueHistoryEntry<Value>> = []
+type ValueHistoryArgs =
+  | {
+      expireDelay?: number
+      maxEntries: number
+    }
+  | {
+      expireDelay: number
+      maxEntries?: number
+    }
 
-  if (!cleanupHistoriesInterval) {
-    cleanupHistoriesInterval = setInterval(() => cleanupHistories(), CLEAR_OLD_VALUES_INTERVAL)
-  }
+export function createValueHistory<Value>({ expireDelay, maxEntries }: ValueHistoryArgs): ValueHistory<Value> {
+  let entries: Array<ValueHistoryEntry<Value>> = []
 
   const clearExpiredValues = () => {
+    if (!expireDelay) {
+      return
+    }
     const oldTimeThreshold = relativeNow() - expireDelay
     while (entries.length > 0 && entries[entries.length - 1].endTime < oldTimeThreshold) {
       entries.pop()
     }
   }
 
-  cleanupTasks.add(clearExpiredValues)
+  if (expireDelay) {
+    if (!cleanupHistoriesInterval) {
+      cleanupHistoriesInterval = setInterval(() => cleanupHistories(), CLEAR_OLD_VALUES_INTERVAL)
+    }
+    cleanupTasks.add(clearExpiredValues)
+  }
 
   /**
    * Add a value to the history associated with a start time. Returns a reference to this newly

packages/browser-logs/src/domain/contexts/sessionContext.ts

@@ -9,10 +9,16 @@ export function startSessionContext(
   sessionManager: SessionManager
 ) {
   hook.register(({ startTime }) => {
+    // Used to attach a (fresh, safe-to-reference) session id: subject to the default
+    // TRACKED_SESSION_MAX_AGE, so it becomes undefined once the session is too old to reference.
     const session = sessionManager.findTrackedSession(startTime)
 
+    // Used for the discard decision: unlike `session` above, this ignores session age (logs
+    // should keep being sent indefinitely, with or without a session, once a session was
+    // legitimately tracked here) but still respects sampling.
     const isSessionTracked = sessionManager.findTrackedSession(startTime, {
       returnInactive: true,
+      maxAge: Infinity,
     })
 
     if (!isSessionTracked) {

test/e2e/scenario/logs.scenario.ts

@@ -1,4 +1,6 @@
 import { DEFAULT_REQUEST_ERROR_RESPONSE_LENGTH_LIMIT } from '@datadog/browser-logs/src/domain/configuration'
+import { ONE_HOUR, ONE_MINUTE } from '@datadog/js-core/time'
+import { SESSION_EXPIRATION_DELAY } from '@datadog/browser-core'
 import { test, expect } from '@playwright/test'
 import { createTest, createWorker } from '../lib/framework'
 import { APPLICATION_ID } from '../lib/helpers/configuration'
@@ -354,4 +356,38 @@ test.describe('logs', () => {
       expect(intakeRegistry.logsEvents).toHaveLength(1)
       expect(intakeRegistry.logsEvents[0].foo).toBe('bar')
     })
+
+  test.describe('session expiration', () => {
+    createTest('logs should keep being sent forever, even long after the session has expired')
+      .withLogs()
+      .withMockClock()
+      .run(async ({ intakeRegistry, flushEvents, page }) => {
+        // Logs should keep being sent indefinitely, with or without a session attached, even
+        // long after the session has expired.
+
+        // Let the session expire from inactivity (no click/scroll/keydown/touch).
+        await page.clock.fastForward(SESSION_EXPIRATION_DELAY + ONE_MINUTE)
+
+        await page.evaluate(() => {
+          window.DD_LOGS!.logger.log('shortly after session expiration')
+        })
+
+        // Fast-forward well past the point where the session is expired.
+        await page.clock.fastForward(24 * ONE_HOUR)
+
+        await page.evaluate(() => {
+          window.DD_LOGS!.logger.log('long after session expiration')
+        })
+
+        await flushEvents()
+
+        expect(intakeRegistry.logsEvents).toHaveLength(2)
+
+        expect(intakeRegistry.logsEvents[0].message).toBe('shortly after session expiration')
+        expect(intakeRegistry.logsEvents[0].session_id).toBeUndefined()
+
+        expect(intakeRegistry.logsEvents[1].message).toBe('long after session expiration')
+        expect(intakeRegistry.logsEvents[1].session_id).toBeUndefined()
+      })
+  })
 })