🐛 Discard views and actions with negative loading time (#1122)

* Discard view and action with negative loading time

packages/rum-core/src/domain/rumEventsCollection/action/trackActions.spec.ts

@@ -35,9 +35,14 @@ describe('trackActions', () => {
   let createSpy: jasmine.Spy
   let discardSpy: jasmine.Spy
 
-  function mockValidatedClickAction(domMutationObservable: Observable<void>, clock: Clock, target: HTMLElement) {
+  function mockValidatedClickAction(
+    domMutationObservable: Observable<void>,
+    clock: Clock,
+    target: HTMLElement,
+    actionDuration: number = BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY
+  ) {
     target.addEventListener(DOM_EVENT.CLICK, () => {
-      clock.tick(BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY)
+      clock.tick(actionDuration)
       // Since we don't collect dom mutations for this test, manually dispatch one
       domMutationObservable.notify()
     })
@@ -121,6 +126,16 @@ describe('trackActions', () => {
     expect(discardSpy).toHaveBeenCalled()
   })
 
+  it('discards a pending action with a negative duration', () => {
+    const { domMutationObservable, clock } = setupBuilder.build()
+    mockValidatedClickAction(domMutationObservable, clock, button, -1)
+    expect(createSpy).toHaveBeenCalled()
+    clock.tick(EXPIRE_DELAY)
+
+    expect(events).toEqual([])
+    expect(discardSpy).toHaveBeenCalled()
+  })
+
   it('ignores a actions if it fails to find a name', () => {
     const { domMutationObservable, clock } = setupBuilder.build()
     mockValidatedClickAction(domMutationObservable, clock, emptyElement)

packages/rum-core/src/domain/rumEventsCollection/action/trackActions.ts

@@ -3,14 +3,12 @@ import {
   Context,
   DOM_EVENT,
   Duration,
-  elapsed,
   generateUUID,
   ClocksState,
   clocksNow,
   Configuration,
   ONE_SECOND,
   Observable,
-  addMonitoringMessage,
 } from '@datadog/browser-core'
 import { ActionType } from '../../../rawRumEvent.types'
 import { LifeCycle, LifeCycleEventType } from '../../lifeCycle'
@@ -104,8 +102,8 @@ function startActionManagement(lifeCycle: LifeCycle, domMutationObservable: Obse
         lifeCycle,
         domMutationObservable,
         (event) => {
-          if (event.hadActivity) {
-            pendingAutoAction.complete(event.endClocks)
+          if (event.hadActivity && event.duration >= 0) {
+            pendingAutoAction.complete(event.duration)
           } else {
             pendingAutoAction.discard()
           }
@@ -125,8 +123,8 @@ function startActionManagement(lifeCycle: LifeCycle, domMutationObservable: Obse
 }
 
 class PendingAutoAction {
+  startClocks: ClocksState
   private id: string
-  private startClocks: ClocksState
   private eventCountsSubscription: { eventCounts: EventCounts; stop(): void }
 
   constructor(private lifeCycle: LifeCycle, private type: AutoActionType, private name: string, private event: Event) {
@@ -136,28 +134,15 @@ class PendingAutoAction {
     this.lifeCycle.notify(LifeCycleEventType.AUTO_ACTION_CREATED, { id: this.id, startClocks: this.startClocks })
   }
 
-  complete(endClocks: ClocksState) {
-    const actionDuration = elapsed(this.startClocks.timeStamp, endClocks.timeStamp)
-    if (actionDuration < 0) {
-      addMonitoringMessage('auto action with negative loading time', {
-        debug: {
-          actionDuration,
-          type: this.type,
-          name: this.name,
-          startClocks: this.startClocks,
-          endClocks,
-        },
-      })
-    }
-
+  complete(duration: Duration) {
     const eventCounts = this.eventCountsSubscription.eventCounts
     this.lifeCycle.notify(LifeCycleEventType.AUTO_ACTION_COMPLETED, {
       counts: {
         errorCount: eventCounts.errorCount,
         longTaskCount: eventCounts.longTaskCount,
         resourceCount: eventCounts.resourceCount,
       },
-      duration: actionDuration,
+      duration,
       id: this.id,
       name: this.name,
       startClocks: this.startClocks,

packages/rum-core/src/domain/rumEventsCollection/view/trackViewMetrics.ts

@@ -1,13 +1,4 @@
-import {
-  Duration,
-  noop,
-  elapsed,
-  round,
-  timeStampNow,
-  RelativeTime,
-  ONE_SECOND,
-  Observable,
-} from '@datadog/browser-core'
+import { Duration, noop, round, RelativeTime, ONE_SECOND, Observable } from '@datadog/browser-core'
 import { RumLayoutShiftTiming, supportPerformanceTimingEvent } from '../../../browser/performanceCollection'
 import { ViewLoadingType } from '../../../rawRumEvent.types'
 import { LifeCycle, LifeCycleEventType } from '../../lifeCycle'
@@ -107,10 +98,9 @@ function trackActivityLoadingTime(
   domMutationObservable: Observable<void>,
   callback: (loadingTimeValue: Duration | undefined) => void
 ) {
-  const startTime = timeStampNow()
-  return waitIdlePage(lifeCycle, domMutationObservable, (params) => {
-    if (params.hadActivity) {
-      callback(elapsed(startTime, params.endClocks.timeStamp))
+  return waitIdlePage(lifeCycle, domMutationObservable, (event) => {
+    if (event.hadActivity) {
+      callback(event.duration)
     } else {
       callback(undefined)
     }

packages/rum-core/src/domain/rumEventsCollection/view/viewCollection.spec.ts

@@ -138,4 +138,13 @@ describe('viewCollection', () => {
     })
     expect(rawRumViewEvent.session.has_replay).toBe(true)
   })
+
+  it('should discard negative loading time', () => {
+    const { lifeCycle, rawRumEvents } = setupBuilder.build()
+    const view = { ...VIEW, loadingTime: -20 as Duration }
+    lifeCycle.notify(LifeCycleEventType.VIEW_UPDATED, view)
+    const rawRumViewEvent = rawRumEvents[rawRumEvents.length - 1].rawRumEvent as RawRumViewEvent
+
+    expect(rawRumViewEvent.view.loading_time).toBeUndefined()
+  })
 })

packages/rum-core/src/domain/rumEventsCollection/view/viewCollection.ts

@@ -6,6 +6,7 @@ import {
   toServerDuration,
   Configuration,
   Observable,
+  isNumber,
 } from '@datadog/browser-core'
 import { RecorderApi } from '../../../boot/rumPublicApi'
 import { RawRumViewEvent, RumEventType } from '../../../rawRumEvent.types'
@@ -72,7 +73,7 @@ function processViewUpdate(
       name: view.name,
       largest_contentful_paint: toServerDuration(view.timings.largestContentfulPaint),
       load_event: toServerDuration(view.timings.loadEvent),
-      loading_time: toServerDuration(view.loadingTime),
+      loading_time: discardNegativeDuration(toServerDuration(view.loadingTime)),
       loading_type: view.loadingType,
       long_task: {
         count: view.eventCounts.longTaskCount,
@@ -101,3 +102,7 @@ function processViewUpdate(
     },
   }
 }
+
+function discardNegativeDuration(duration: ServerDuration | undefined): ServerDuration | undefined {
+  return isNumber(duration) && duration < 0 ? undefined : duration
+}

packages/rum-core/src/domain/waitIdlePage.spec.ts

@@ -1,4 +1,4 @@
-import { Observable, ONE_SECOND, TimeStamp, timeStampNow } from '@datadog/browser-core'
+import { Observable, ONE_SECOND } from '@datadog/browser-core'
 import { Clock, mockClock } from '@datadog/browser-core/test/specHelper'
 import { RumPerformanceNavigationTiming, RumPerformanceResourceTiming } from '../browser/performanceCollection'
 import { LifeCycle, LifeCycleEventType } from './lifeCycle'
@@ -166,7 +166,6 @@ describe('doWaitIdlePage', () => {
   it('should collect an event that is followed by page activity', () => {
     const activityObservable = new Observable<PageActivityEvent>()
 
-    const startTime = timeStampNow()
     doWaitIdlePage(activityObservable, idlPageActivityCallbackSpy)
 
     clock.tick(BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY)
@@ -176,18 +175,13 @@ describe('doWaitIdlePage', () => {
 
     expect(idlPageActivityCallbackSpy).toHaveBeenCalledOnceWith({
       hadActivity: true,
-      endClocks: {
-        // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
-        timeStamp: (startTime + BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY) as TimeStamp,
-        relative: BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY,
-      },
+      duration: BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY,
     })
   })
 
   describe('extend with activities', () => {
     it('is extended while there is page activities', () => {
       const activityObservable = new Observable<PageActivityEvent>()
-      const startTime = timeStampNow()
       // Extend the action 10 times
       const extendCount = 10
 
@@ -200,21 +194,15 @@ describe('doWaitIdlePage', () => {
 
       clock.tick(EXPIRE_DELAY)
 
-      const relative = extendCount * BEFORE_PAGE_ACTIVITY_END_DELAY
       expect(idlPageActivityCallbackSpy).toHaveBeenCalledOnceWith({
         hadActivity: true,
-        endClocks: {
-          // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
-          timeStamp: (startTime + relative) as TimeStamp,
-          relative,
-        },
+        duration: extendCount * BEFORE_PAGE_ACTIVITY_END_DELAY,
       })
     })
 
     it('expires after a maximum duration', () => {
       const activityObservable = new Observable<PageActivityEvent>()
       let stop = false
-      const startTime = timeStampNow()
 
       // Extend the action until it's more than MAX_DURATION
       const extendCount = Math.ceil(MAX_DURATION / BEFORE_PAGE_ACTIVITY_END_DELAY + 1)
@@ -233,19 +221,14 @@ describe('doWaitIdlePage', () => {
 
       expect(idlPageActivityCallbackSpy).toHaveBeenCalledOnceWith({
         hadActivity: true,
-        endClocks: {
-          // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
-          timeStamp: (startTime + MAX_DURATION) as TimeStamp,
-          relative: MAX_DURATION,
-        },
+        duration: MAX_DURATION,
       })
     })
   })
 
   describe('busy activities', () => {
     it('is extended while the page is busy', () => {
       const activityObservable = new Observable<PageActivityEvent>()
-      const startTime = timeStampNow()
       doWaitIdlePage(activityObservable, idlPageActivityCallbackSpy)
 
       clock.tick(BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY)
@@ -256,20 +239,14 @@ describe('doWaitIdlePage', () => {
 
       clock.tick(EXPIRE_DELAY)
 
-      const relative = BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY + PAGE_ACTIVITY_END_DELAY * 2
       expect(idlPageActivityCallbackSpy).toHaveBeenCalledOnceWith({
         hadActivity: true,
-        endClocks: {
-          // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
-          timeStamp: (startTime + relative) as TimeStamp,
-          relative,
-        },
+        duration: BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY + PAGE_ACTIVITY_END_DELAY * 2,
       })
     })
 
     it('expires is the page is busy for too long', () => {
       const activityObservable = new Observable<PageActivityEvent>()
-      const startTime = timeStampNow()
       doWaitIdlePage(activityObservable, idlPageActivityCallbackSpy, MAX_DURATION)
 
       clock.tick(BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY)
@@ -279,11 +256,7 @@ describe('doWaitIdlePage', () => {
 
       expect(idlPageActivityCallbackSpy).toHaveBeenCalledOnceWith({
         hadActivity: true,
-        endClocks: {
-          // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
-          timeStamp: (startTime + MAX_DURATION) as TimeStamp,
-          relative: MAX_DURATION,
-        },
+        duration: MAX_DURATION,
       })
     })
   })

packages/rum-core/src/domain/waitIdlePage.ts

@@ -1,4 +1,4 @@
-import { clocksNow, ClocksState, monitor, Observable, Subscription } from '@datadog/browser-core'
+import { Duration, elapsed, monitor, Observable, Subscription, timeStampNow } from '@datadog/browser-core'
 import { LifeCycle, LifeCycleEventType } from './lifeCycle'
 
 // Delay to wait for a page activity to validate the tracking process
@@ -10,7 +10,7 @@ export interface PageActivityEvent {
   isBusy: boolean
 }
 
-export type IdlePageEvent = { hadActivity: true; endClocks: ClocksState } | { hadActivity: false }
+export type IdlePageEvent = { hadActivity: true; duration: Duration } | { hadActivity: false }
 
 /**
  * Wait for the next idle page time
@@ -59,6 +59,7 @@ export function doWaitIdlePage(
 ) {
   let idleTimeoutId: number
   let hasCompleted = false
+  const startTime = timeStampNow()
 
   const validationTimeoutId = setTimeout(
     monitor(() => complete({ hadActivity: false })),
@@ -67,17 +68,17 @@ export function doWaitIdlePage(
   const maxDurationTimeoutId =
     maxDuration &&
     setTimeout(
-      monitor(() => complete({ hadActivity: true, endClocks: clocksNow() })),
+      monitor(() => complete({ hadActivity: true, duration: elapsed(startTime, timeStampNow()) })),
       maxDuration
     )
 
   const pageActivitySubscription = pageActivityObservable.subscribe(({ isBusy }) => {
     clearTimeout(validationTimeoutId)
     clearTimeout(idleTimeoutId)
-    const lastChangeTime = clocksNow()
+    const lastChangeTime = timeStampNow()
     if (!isBusy) {
       idleTimeoutId = setTimeout(
-        monitor(() => complete({ hadActivity: true, endClocks: lastChangeTime })),
+        monitor(() => complete({ hadActivity: true, duration: elapsed(startTime, lastChangeTime) })),
         PAGE_ACTIVITY_END_DELAY
       )
     }