Update Fireperf logging to use sendBeacon only if the payload is under the 64KB limit

.changeset/nervous-needles-sit.md

@@ -0,0 +1,5 @@
+---
+'@firebase/performance': patch
+---
+
+Fix bug where events are not sent if they exceed sendBeacon payload limit

packages/performance/src/services/transport_service.test.ts

@@ -21,7 +21,8 @@ import sinonChai from 'sinon-chai';
 import {
   transportHandler,
   setupTransportService,
-  resetTransportService
+  resetTransportService,
+  flushQueuedEvents
 } from './transport_service';
 import { SettingsService } from './settings_service';
 
@@ -88,7 +89,7 @@ describe('Firebase Performance > transport_service', () => {
     expect(fetchStub).to.not.have.been.called;
   });
 
-  it('sends up to the maximum event limit in one request', async () => {
+  it('sends up to the maximum event limit in one request if payload is under 64 KB', async () => {
     // Arrange
     const setting = SettingsService.getInstance();
     const flTransportFullUrl =
@@ -134,6 +135,58 @@ describe('Firebase Performance > transport_service', () => {
     expect(fetchStub).to.not.have.been.called;
   });
 
+  it('sends fetch if payload is above 64 KB', async () => {
+    // Arrange
+    const setting = SettingsService.getInstance();
+    const flTransportFullUrl =
+      setting.flTransportEndpointUrl + '?key=' + setting.transportKey;
+    fetchStub.resolves(
+      new Response('{}', {
+        status: 200,
+        headers: { 'Content-type': 'application/json' }
+      })
+    );
+
+    const payload = 'a'.repeat(300);
+    // Act
+    // Generate 1020 events
+    for (let i = 0; i < 1020; i++) {
+      testTransportHandler(payload + i);
+    }
+    // Wait for first and second event dispatch to happen.
+    clock.tick(INITIAL_SEND_TIME_DELAY_MS);
+    // This is to resolve the floating promise chain in transport service.
+    await Promise.resolve().then().then().then();
+    clock.tick(DEFAULT_SEND_INTERVAL_MS);
+
+    // Assert
+    // Expects the first logRequest which contains first 1000 events.
+    const firstLogRequest = generateLogRequest('5501');
+    for (let i = 0; i < MAX_EVENT_COUNT_PER_REQUEST; i++) {
+      firstLogRequest['log_event'].push({
+        'source_extension_json_proto3': payload + i,
+        'event_time_ms': '1'
+      });
+    }
+    expect(fetchStub).calledWith(flTransportFullUrl, {
+      method: 'POST',
+      body: JSON.stringify(firstLogRequest)
+    });
+    // Expects the second logRequest which contains remaining 20 events;
+    const secondLogRequest = generateLogRequest('15501');
+    for (let i = 0; i < 20; i++) {
+      secondLogRequest['log_event'].push({
+        'source_extension_json_proto3':
+          payload + (MAX_EVENT_COUNT_PER_REQUEST + i),
+        'event_time_ms': '1'
+      });
+    }
+    expect(sendBeaconStub).calledWith(
+      flTransportFullUrl,
+      JSON.stringify(secondLogRequest)
+    );
+  });
+
   it('falls back to fetch if sendBeacon fails.', async () => {
     sendBeaconStub.returns(false);
     fetchStub.resolves(
@@ -147,6 +200,98 @@ describe('Firebase Performance > transport_service', () => {
     expect(fetchStub).to.have.been.calledOnce;
   });
 
+  it('flushes the queue with multiple sendBeacons in batches of 40', async () => {
+    // Arrange
+    const setting = SettingsService.getInstance();
+    const flTransportFullUrl =
+      setting.flTransportEndpointUrl + '?key=' + setting.transportKey;
+    fetchStub.resolves(
+      new Response('{}', {
+        status: 200,
+        headers: { 'Content-type': 'application/json' }
+      })
+    );
+
+    const payload = 'a'.repeat(300);
+    // Act
+    // Generate 80 events
+    for (let i = 0; i < 80; i++) {
+      testTransportHandler(payload + i);
+    }
+
+    flushQueuedEvents();
+
+    // Assert
+    const firstLogRequest = generateLogRequest('1');
+    const secondLogRequest = generateLogRequest('1');
+    for (let i = 0; i < 40; i++) {
+      firstLogRequest['log_event'].push({
+        'source_extension_json_proto3': payload + (i + 40),
+        'event_time_ms': '1'
+      });
+      secondLogRequest['log_event'].push({
+        'source_extension_json_proto3': payload + i,
+        'event_time_ms': '1'
+      });
+    }
+    expect(sendBeaconStub).calledWith(
+      flTransportFullUrl,
+      JSON.stringify(firstLogRequest)
+    );
+    expect(sendBeaconStub).calledWith(
+      flTransportFullUrl,
+      JSON.stringify(secondLogRequest)
+    );
+    expect(fetchStub).to.not.have.been.called;
+  });
+
+  it('flushes the queue with fetch for sendBeacons that failed', async () => {
+    // Arrange
+    const setting = SettingsService.getInstance();
+    const flTransportFullUrl =
+      setting.flTransportEndpointUrl + '?key=' + setting.transportKey;
+    fetchStub.resolves(
+      new Response('{}', {
+        status: 200,
+        headers: { 'Content-type': 'application/json' }
+      })
+    );
+
+    const payload = 'a'.repeat(300);
+    // Act
+    // Generate 80 events
+    for (let i = 0; i < 80; i++) {
+      testTransportHandler(payload + i);
+    }
+    sendBeaconStub.onCall(0).returns(true);
+    sendBeaconStub.onCall(1).returns(false);
+    flushQueuedEvents();
+
+    // Assert
+    const firstLogRequest = generateLogRequest('1');
+    const secondLogRequest = generateLogRequest('1');
+    for (let i = 40; i < 80; i++) {
+      firstLogRequest['log_event'].push({
+        'source_extension_json_proto3': payload + i,
+        'event_time_ms': '1'
+      });
+    }
+    for (let i = 0; i < 40; i++) {
+      secondLogRequest['log_event'].push({
+        'source_extension_json_proto3': payload + i,
+        'event_time_ms': '1'
+      });
+    }
+    expect(sendBeaconStub).calledWith(
+      flTransportFullUrl,
+      JSON.stringify(firstLogRequest)
+    );
+    expect(fetchStub).calledWith(flTransportFullUrl, {
+      method: 'POST',
+      body: JSON.stringify(secondLogRequest)
+    });
+  });
+
   function generateLogRequest(requestTimeMs: string): any {
     return {
       'request_time_ms': requestTimeMs,

packages/performance/src/services/transport_service.ts

@@ -24,6 +24,14 @@ const INITIAL_SEND_TIME_DELAY_MS = 5.5 * 1000;
 const MAX_EVENT_COUNT_PER_REQUEST = 1000;
 const DEFAULT_REMAINING_TRIES = 3;
 
+// Most browsers have a max payload of 64KB for sendbeacon/keep alive payload.
+const MAX_SEND_BEACON_PAYLOAD_SIZE = 65536;
+// The max number of events to send during a flush. This number is kept low to since Chrome has a
+// shared payload limit for all sendBeacon calls in the same nav context.
+const MAX_FLUSH_SIZE = 40;
+
+const TEXT_ENCODER = new TextEncoder();
+
 let remainingTries = DEFAULT_REMAINING_TRIES;
 
 interface BatchEvent {
@@ -90,14 +98,31 @@ function dispatchQueueEvents(): void {
   // for next attempt.
   const staged = queue.splice(0, MAX_EVENT_COUNT_PER_REQUEST);
 
+  const data = buildPayload(staged);
+
+  postToFlEndpoint(data)
+    .then(() => {
+      remainingTries = DEFAULT_REMAINING_TRIES;
+    })
+    .catch(() => {
+      // If the request fails for some reason, add the events that were attempted
+      // back to the primary queue to retry later.
+      queue = [...staged, ...queue];
+      remainingTries--;
+      consoleLogger.info(`Tries left: ${remainingTries}.`);
+      processQueue(DEFAULT_SEND_INTERVAL_MS);
+    });
+}
+
+function buildPayload(events: BatchEvent[]): string {
   /* eslint-disable camelcase */
   // We will pass the JSON serialized event to the backend.
-  const log_event: Log[] = staged.map(evt => ({
+  const log_event: Log[] = events.map(evt => ({
     source_extension_json_proto3: evt.message,
     event_time_ms: String(evt.eventTime)
   }));
 
-  const data: TransportBatchLogFormat = {
+  const transportBatchLog: TransportBatchLogFormat = {
     request_time_ms: String(Date.now()),
     client_info: {
       client_type: 1, // 1 is JS
@@ -108,32 +133,27 @@ function dispatchQueueEvents(): void {
   };
   /* eslint-enable camelcase */
 
-  postToFlEndpoint(data)
-    .then(() => {
-      remainingTries = DEFAULT_REMAINING_TRIES;
-    })
-    .catch(() => {
-      // If the request fails for some reason, add the events that were attempted
-      // back to the primary queue to retry later.
-      queue = [...staged, ...queue];
-      remainingTries--;
-      consoleLogger.info(`Tries left: ${remainingTries}.`);
-      processQueue(DEFAULT_SEND_INTERVAL_MS);
-    });
+  return JSON.stringify(transportBatchLog);
 }
 
-function postToFlEndpoint(data: TransportBatchLogFormat): Promise<void> {
+/** Sends to Firelog. Atempts to use sendBeacon otherwsise uses fetch. */
+function postToFlEndpoint(body: string): Promise<void | Response> {
   const flTransportFullUrl =
     SettingsService.getInstance().getFlTransportFullUrl();
-  const body = JSON.stringify(data);
-
-  return navigator.sendBeacon && navigator.sendBeacon(flTransportFullUrl, body)
-    ? Promise.resolve()
-    : fetch(flTransportFullUrl, {
-        method: 'POST',
-        body,
-        keepalive: true
-      }).then();
+  const size = TEXT_ENCODER.encode(body).length;
+
+  if (
+    size <= MAX_SEND_BEACON_PAYLOAD_SIZE &&
+    navigator.sendBeacon &&
+    navigator.sendBeacon(flTransportFullUrl, body)
+  ) {
+    return Promise.resolve();
+  } else {
+    return fetch(flTransportFullUrl, {
+      method: 'POST',
+      body
+    });
+  }
 }
 
 function addToQueue(evt: BatchEvent): void {
@@ -159,11 +179,36 @@ export function transportHandler(
 }
 
 /**
- * Force flush the queued events. Useful at page unload time to ensure all
- * events are uploaded.
+ * Force flush the queued events. Useful at page unload time to ensure all events are uploaded.
+ * Flush will attempt to use sendBeacon to send events async and defaults back to fetch as soon as a
+ * sendBeacon fails. Firefox
  */
 export function flushQueuedEvents(): void {
+  const flTransportFullUrl =
+    SettingsService.getInstance().getFlTransportFullUrl();
+
   while (queue.length > 0) {
-    dispatchQueueEvents();
+    // Send the last events first to prioritize page load traces
+    const staged = queue.splice(-MAX_FLUSH_SIZE);
+    const body = buildPayload(staged);
+
+    if (
+      navigator.sendBeacon &&
+      navigator.sendBeacon(flTransportFullUrl, body)
+    ) {
+      continue;
+    } else {
+      queue = [...queue, ...staged];
+      break;
+    }
+  }
+  if (queue.length > 0) {
+    const body = buildPayload(queue);
+    fetch(flTransportFullUrl, {
+      method: 'POST',
+      body
+    }).catch(() => {
+      consoleLogger.info(`Failed flushing queued events.`);
+    });
   }
 }