Worker: support optional batching of log events (#1162)

* worker: re-write core event handler to allow more control of sequencing

* tidy tests and finish

* types

* add basic tests

* more testing

* Add batching and tests

* more tests

* options and more tests

* types

* copy new log stuff from other branch

* updates for live testing against lightning

Works great against new and legacy app, with or without batching

* options for interval and limit

* fix test

* copy across old test

* fix type

* add batch log test

* upate default batch size

* changeset

* run integration tests in batch mode

* update tests

* remove logging

* docs

Author: josephjclark

.changeset/fair-papayas-stop.md

@@ -0,0 +1,5 @@
+---
+'@openfn/ws-worker': minor
+---
+
+Allow logs to be sent to Lightning in batches. This behavior is disabled by default for back-compatibility: set `WORKER_BATCH_LOGS=true` to enable.

integration-tests/worker/src/init.ts

@@ -47,6 +47,7 @@ export const initWorker = async (
     secret: crypto.randomUUID(),
     collectionsVersion: '1.0.0',
     messageTimeoutSeconds: 0.01,
+    batchLogs: true,
     ...workerArgs,
   });
 

integration-tests/worker/test/integration.test.ts

@@ -988,9 +988,11 @@ test.serial('Redact logs which exceed the payload limit', (t) => {
     };
 
     lightning.on('run:log', (evt) => {
-      if (evt.payload.source === 'JOB') {
-        t.regex(evt.payload.message[0], /redacted/i);
-      }
+      evt.payload.logs.forEach((log) => {
+        if (log.source === 'JOB') {
+          t.regex(log.message[0], /redacted/i);
+        }
+      });
     });
 
     lightning.enqueueRun(run);
@@ -1066,11 +1068,13 @@ test.serial(
       const rtLogs = [];
 
       lightning.on('run:log', (e) => {
-        if (e.payload.source === 'JOB') {
-          jobLogs.push(e.payload);
-        } else if (e.payload.source === 'R/T') {
-          rtLogs.push(e.payload);
-        }
+        e.payload.logs.forEach((log) => {
+          if (log.source === 'JOB') {
+            jobLogs.push(log);
+          } else if (log.source === 'R/T') {
+            rtLogs.push(log);
+          }
+        });
       });
 
       lightning.once('run:complete', () => {

packages/lexicon/lightning.d.ts

@@ -173,15 +173,23 @@ export type RunCompletePayload = ExitReason & {
 };
 export type RunCompleteReply = undefined;
 
-export type RunLogPayload = {
+export type RunLogLine = {
   message: Array<string | object>;
   timestamp: TimeInMicroSeconds;
-  run_id: string;
   level?: string;
   source?: string; // namespace
-  job_id?: string;
   step_id?: string;
 };
+
+export type RunLogPayload = {
+  run_id: string;
+  logs: RunLogLine[];
+};
+
+export type LegacyRunLogPayload = {
+  run_id: string;
+} & RunLogLine;
+
 export type RunLogReply = void;
 
 export type StepStartPayload = {

packages/lightning-mock/src/api-sockets.ts

@@ -21,6 +21,7 @@ import type {
   StepCompleteReply,
   StepStartPayload,
   StepStartReply,
+  LegacyRunLogPayload,
 } from '@openfn/lexicon/lightning';
 
 import createPheonixMockSocketServer, {
@@ -320,27 +321,41 @@ const createSocketAPI = (
     evt: PhoenixEvent<RunLogPayload>
   ) {
     const { ref, join_ref, topic } = evt;
-    const { run_id: runId } = evt.payload;
-
-    state.pending[runId].logs.push(evt.payload);
 
     let payload: any = {
       status: 'ok',
     };
 
-    if (
-      !evt.payload.message ||
-      !evt.payload.source ||
-      !evt.payload.timestamp ||
-      !evt.payload.level
-    ) {
-      payload = {
-        status: 'error',
-        response: 'Missing property on log',
-      };
-    }
+    const { run_id: runId } = evt.payload;
+
+    if (evt.payload.logs) {
+      // handle batch logs
+      evt.payload.logs.forEach((log) => {
+        state.pending[runId].logs.push(log);
 
-    logger?.info(`LOG [${runId}] ${evt.payload.message[0]}`);
+        logger?.info(`LOG [${runId}] ${log.message}`);
+
+        if (!log.message || !log.source || !log.timestamp || !log.level) {
+          payload = {
+            status: 'error',
+            response: 'Missing property on log',
+          };
+        }
+      });
+    } else {
+      // handle legacy logs
+      const log = evt.payload as unknown as LegacyRunLogPayload;
+      state.pending[runId].logs.push(log);
+
+      logger?.info(`LOG [${runId}] ${log.message}`);
+
+      if (!log.message || !log.source || !log.timestamp || !log.level) {
+        payload = {
+          status: 'error',
+          response: 'Missing property on log',
+        };
+      }
+    }
 
     ws.reply<RunLogReply>({
       ref,

packages/lightning-mock/src/server.ts

@@ -8,7 +8,7 @@ import createLogger, {
   Logger,
 } from '@openfn/logger';
 import type { StepId } from '@openfn/lexicon';
-import type { RunLogPayload, LightningPlan } from '@openfn/lexicon/lightning';
+import type { LightningPlan, RunLogLine } from '@openfn/lexicon/lightning';
 
 import createWebSocketAPI from './api-sockets';
 import createDevAPI from './api-dev';
@@ -20,7 +20,7 @@ type JobId = string;
 
 export type RunState = {
   status: 'queued' | 'started' | 'complete';
-  logs: RunLogPayload[];
+  logs: RunLogLine[];
   steps: Record<JobId, StepId>;
 };
 

packages/lightning-mock/test/events/log.test.ts

@@ -18,10 +18,14 @@ test.serial('acknowledge valid message (run log)', async (t) => {
 
     const event = {
       run_id: run.id,
-      message: 'blah',
-      level: 'info',
-      source: 'R/T',
-      timestamp: '123',
+      logs: [
+        {
+          message: 'blah',
+          level: 'info',
+          source: 'R/T',
+          timestamp: '123',
+        },
+      ],
     };
 
     const channel = await join(client, run.id);
@@ -41,11 +45,15 @@ test.serial('acknowledge valid message (job log)', async (t) => {
 
     const event = {
       run_id: run.id,
-      job_id: 'a',
-      message: 'blah',
-      level: 'info',
-      source: 'R/T',
-      timestamp: '123',
+      logs: [
+        {
+          job_id: 'a',
+          message: 'blah',
+          level: 'info',
+          source: 'R/T',
+          timestamp: '123',
+        },
+      ],
     };
 
     const channel = await join(client, run.id);
@@ -65,19 +73,23 @@ test.serial('save log to state', async (t) => {
 
     const event = {
       run_id: run.id,
-      job_id: 'a',
-      message: 'blah',
-      level: 'info',
-      source: 'R/T',
-      timestamp: '123',
+      logs: [
+        {
+          job_id: 'a',
+          message: 'blah',
+          level: 'info',
+          source: 'R/T',
+          timestamp: '123',
+        },
+      ],
     };
 
     const channel = await join(client, run.id);
 
     channel.push(RUN_LOG, event).receive('ok', () => {
       const { pending } = server.getState();
       const [savedLog] = pending[run.id].logs;
-      t.deepEqual(savedLog, event);
+      t.deepEqual(savedLog, event.logs[0]);
       done();
     });
   });
@@ -91,10 +103,14 @@ test.serial('error if no message', async (t) => {
 
     const event = {
       run_id: run.id,
-      job_id: 'a',
-      level: 'info',
-      source: 'R/T',
-      timestamp: '123',
+      logs: [
+        {
+          job_id: 'a',
+          level: 'info',
+          source: 'R/T',
+          timestamp: '123',
+        },
+      ],
     };
     const channel = await join(client, run.id);
 
@@ -113,10 +129,14 @@ test.serial('error if no source', async (t) => {
 
     const event = {
       run_id: run.id,
-      job_id: 'a',
-      message: 'blah',
-      level: 'info',
-      timestamp: '123',
+      logs: [
+        {
+          job_id: 'a',
+          message: 'blah',
+          level: 'info',
+          timestamp: '123',
+        },
+      ],
     };
     const channel = await join(client, run.id);
 
@@ -135,9 +155,13 @@ test.serial('error if no timestamp', async (t) => {
 
     const event = {
       run_id: run.id,
-      message: 'blah',
-      level: 'info',
-      source: 'R/T',
+      logs: [
+        {
+          message: 'blah',
+          level: 'info',
+          source: 'R/T',
+        },
+      ],
     };
     const channel = await join(client, run.id);
 
@@ -156,10 +180,14 @@ test.serial('error if no level', async (t) => {
 
     const event = {
       run_id: run.id,
-      job_id: 'a',
-      message: 'blah',
-      source: 'R/T',
-      timestamp: '123',
+      logs: [
+        {
+          job_id: 'a',
+          message: 'blah',
+          source: 'R/T',
+          timestamp: '123',
+        },
+      ],
     };
     const channel = await join(client, run.id);