Merge pull request #445 from OpenFn/hrtime

High resolution timestamps

integration-tests/worker/CHANGELOG.md

@@ -1,5 +1,23 @@
 # @openfn/integration-tests-worker
 
+## 1.0.9
+
+### Patch Changes
+
+- Updated dependencies [b8fd13d]
+  - @openfn/ws-worker@0.1.8
+
+## 1.0.8
+
+### Patch Changes
+
+- Updated dependencies [8f7f57b]
+- Updated dependencies [ca701e8]
+  - @openfn/ws-worker@0.1.7
+  - @openfn/logger@0.0.19
+  - @openfn/engine-multi@0.1.5
+  - @openfn/lightning-mock@1.0.6
+
 ## 1.0.7
 
 ### Patch Changes

integration-tests/worker/package.json

@@ -1,7 +1,7 @@
 {
   "name": "@openfn/integration-tests-worker",
   "private": true,
-  "version": "1.0.7",
+  "version": "1.0.9",
   "description": "Lightning WOrker integration tests",
   "author": "Open Function Group <admin@openfn.org>",
   "license": "ISC",

packages/cli/CHANGELOG.md

@@ -1,5 +1,15 @@
 # @openfn/cli
 
+## 0.4.3
+
+### Patch Changes
+
+- Updated dependencies [ca701e8]
+  - @openfn/logger@0.0.19
+  - @openfn/compiler@0.0.38
+  - @openfn/deploy@0.2.9
+  - @openfn/runtime@0.0.33
+
 ## 0.4.2
 
 ### Patch Changes

packages/cli/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@openfn/cli",
-  "version": "0.4.2",
+  "version": "0.4.3",
   "description": "CLI devtools for the openfn toolchain.",
   "engines": {
     "node": ">=18",

packages/compiler/CHANGELOG.md

@@ -1,5 +1,12 @@
 # @openfn/compiler
 
+## 0.0.38
+
+### Patch Changes
+
+- Updated dependencies [ca701e8]
+  - @openfn/logger@0.0.19
+
 ## 0.0.37
 
 ### Patch Changes

packages/compiler/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@openfn/compiler",
-  "version": "0.0.37",
+  "version": "0.0.38",
   "description": "Compiler and language tooling for openfn jobs.",
   "author": "Open Function Group <admin@openfn.org>",
   "license": "ISC",

packages/deploy/CHANGELOG.md

@@ -1,5 +1,12 @@
 # @openfn/deploy
 
+## 0.2.9
+
+### Patch Changes
+
+- Updated dependencies [ca701e8]
+  - @openfn/logger@0.0.19
+
 ## 0.2.8
 
 ### Patch Changes

packages/deploy/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@openfn/deploy",
-  "version": "0.2.8",
+  "version": "0.2.9",
   "description": "Deploy projects to Lightning instances",
   "type": "module",
   "exports": {

packages/engine-multi/CHANGELOG.md

@@ -1,5 +1,14 @@
 # engine-multi
 
+## 0.1.5
+
+### Patch Changes
+
+- Updated dependencies [ca701e8]
+  - @openfn/logger@0.0.19
+  - @openfn/compiler@0.0.38
+  - @openfn/runtime@0.0.33
+
 ## 0.1.4
 
 ### Patch Changes

packages/engine-multi/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@openfn/engine-multi",
-  "version": "0.1.4",
+  "version": "0.1.5",
   "description": "Multi-process runtime engine",
   "main": "dist/index.js",
   "type": "module",

packages/engine-multi/src/events.ts

@@ -16,6 +16,8 @@ export const JOB_START = 'job-start';
 
 export const JOB_COMPLETE = 'job-complete';
 
+// TODO To be fair this is just a log, not neccesarily a workflow log
+// A log line may have a workflow and job id
 export const WORKFLOW_LOG = 'workflow-log';
 
 export const WORKFLOW_EDGE_RESOLVED = 'workflow-edge-resolved';

packages/engine-multi/test/api/execute.test.ts

@@ -155,6 +155,32 @@ test.serial('should emit a log event', async (t) => {
   t.is(workflowLog.level, 'info');
 });
 
+test.serial('log events are timestamped in hr time', async (t) => {
+  let workflowLog;
+  const plan = {
+    id: 'y',
+    jobs: [
+      {
+        expression: '() => { console.log("hi"); return 33 }',
+      },
+    ],
+  };
+  const state = {
+    id: 'y',
+    plan,
+  } as WorkflowState;
+
+  const context = createContext({ state, options });
+  context.once(WORKFLOW_LOG, (evt) => (workflowLog = evt));
+
+  await execute(context);
+  const { time } = workflowLog;
+
+  // Note: The time we get here is NOT a bigint because it's been serialized
+  t.true(typeof time === 'string');
+  t.is(time.length, 19);
+});
+
 test.serial('should emit error on timeout', async (t) => {
   const state = {
     id: 'zz',

packages/lightning-mock/CHANGELOG.md

@@ -1,5 +1,14 @@
 # @openfn/lightning-mock
 
+## 1.0.6
+
+### Patch Changes
+
+- Updated dependencies [ca701e8]
+  - @openfn/logger@0.0.19
+  - @openfn/engine-multi@0.1.5
+  - @openfn/runtime@0.0.33
+
 ## 1.0.5
 
 ### Patch Changes

packages/lightning-mock/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@openfn/lightning-mock",
-  "version": "1.0.5",
+  "version": "1.0.6",
   "private": true,
   "description": "A mock Lightning server",
   "main": "dist/index.js",

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

@@ -130,11 +130,14 @@ const setupDevAPI = (
   app.onSocketEvent = (
     event: LightningEvents,
     attemptId: string,
-    fn: (evt: any) => void
+    fn: (evt: any) => void,
+    once = true,
   ) => {
     function handler(e: any) {
       if (e.attemptId && e.attemptId === attemptId) {
-        state.events.removeListener(event, handler);
+        if (once) {
+          state.events.removeListener(event, handler);
+        }
         fn(e);
       }
     }

packages/logger/CHANGELOG.md

@@ -1,5 +1,11 @@
 # @openfn/logger
 
+## 0.0.19
+
+### Patch Changes
+
+- ca701e8: Log json with high-resolution timestamp
+
 ## 0.0.18
 
 ### Patch Changes

packages/logger/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@openfn/logger",
-  "version": "0.0.18",
+  "version": "0.0.19",
   "description": "Cross-package logging utility",
   "module": "dist/index.js",
   "author": "Open Function Group <admin@openfn.org>",

packages/logger/src/index.ts

@@ -2,13 +2,14 @@ import createLogger from './logger';
 import createMockLogger from './mock';
 import isValidLogLevel from './util/is-valid-log-level';
 import printDuration from './util/duration';
+import timestamp from './util/timestamp'
 
-export { createMockLogger, isValidLogLevel, printDuration };
+export { createMockLogger, isValidLogLevel, printDuration, timestamp };
 
 export const defaultLogger = createLogger();
 
 export default createLogger;
 
 export type { Logger, JSONLog, StringLog } from './logger';
 export type { LogOptions, LogLevel } from './options';
-export type { SanitizePolicies } from './sanitize';
+export type { SanitizePolicies } from './sanitize';

packages/logger/src/logger.ts

@@ -4,6 +4,7 @@ import stringify from 'fast-safe-stringify';
 import * as symbols from './symbols';
 import sanitize from './sanitize';
 import getDurationString from './util/duration';
+import hrtimestamp from './util/timestamp';
 import ensureOptions, { LogOptions, LogLevel } from './options';
 
 // Nice clean log level definitions
@@ -48,7 +49,7 @@ export type JSONLog = {
   message: Array<string | object | any>;
   level: LogFns;
   name?: string;
-  time: number;
+  time: string;
 };
 
 export type StringLog = [LogFns | 'confirm' | 'print', ...any];
@@ -174,10 +175,9 @@ export default function (name?: string, options: LogOptions = {}): Logger {
       level,
       name,
       message,
-      time: Date.now(),
+      time: hrtimestamp().toString(),
     };
 
-    stringify(output);
     emitter[level](stringify(output));
   };
 

packages/logger/src/util/timestamp.ts

@@ -0,0 +1,12 @@
+// Take a snapshot of the time-on-load load at nanosecond precision
+// We use this as a base to calculate timestamps later
+const start = BigInt(Date.now()) * BigInt(1e6);
+
+const startDiff = process.hrtime.bigint()
+
+// The timestamp is: workout the time elapsed (in nanoseconds) and add that to the start date
+export default () => start + (process.hrtime.bigint() - startDiff)
+
+// Util to convert a bigint timestamp to a date
+export const timestampToDate = (time: bigint) =>
+  new Date(Number(time / BigInt(1e6)));

packages/logger/test/logger.test.ts

@@ -2,12 +2,14 @@ import test from 'ava';
 import chalk from 'chalk';
 import { styleLevel, LogFns, StringLog } from '../src/logger';
 import { defaults as defaultOptions, LogLevel } from '../src/options';
+import hrtimestamp from '../src/util/timestamp';
 import { SECRET } from '../src/sanitize';
 
 // We're going to run all these tests against the mock logger
 // Which is basically thin wrapper around the logger which bypasses
 // console and provides an inspection API
 import createLogger from '../src/mock';
+import { timestampToDate } from '../src/util/timestamp';
 
 const wait = (ms: number) => {
   return new Promise((resolve) => {
@@ -201,10 +203,66 @@ test('sanitize: summarise object', (t) => {
     t.assert(result.level === level);
     t.assert(result.name === 'x');
     t.assert(result.message[0] === 'abc');
-    t.true(!isNaN(result.time));
+    t.is(typeof result.time, 'string');
   });
 });
 
+test(`JSON timestamps are bigints representing sensible times`, (t) => {
+  const testStartTime = new Date().toISOString()
+  const startTime = hrtimestamp();
+
+  const options = { level: 'info' as const, json: true };
+  const logger = createLogger<string>('x', options);
+  logger.info("what's the time mr wolf");
+
+  const { time } = JSON.parse(logger._last);
+  // The time we get here is NOT a bigint because it's been serialized
+  t.true(typeof time === 'string');
+  t.is(time.length, 19);
+
+  // But we can convert it and check the value is sensible
+  const endTime = BigInt(time);
+
+  const endDate = timestampToDate(endTime);
+
+  // These dates, captured at different resolutions and converte to ms,
+  // are probabably identical, maybe <3ms difference
+  t.log(`log time: ${testStartTime}
+big start time: ${timestampToDate(startTime).toISOString()},
+big end time: ${endDate.toISOString()}`);
+
+  // tinfoil hat: make sure the result is the same day at least
+  // Maybe a time diff < 1e6 is a better test but this is really belt and braces
+  const today = new Date();
+  t.is(today.getDate(), endDate.getDate());
+  t.is(today.getFullYear(), endDate.getFullYear());
+  t.is(today.getMonth(), endDate.getMonth());
+
+  t.true(endTime >= startTime);
+
+  // Check the elapsed time is less than, say, 1ms (should be super super quick!)
+  t.true(endTime - startTime < 1e6);
+});
+
+// TODO this test needs to pass without the timeout
+test('timestamps increase in time', async (t) => {
+  const options = { level: 'info' as const, json: true };
+  const logger = createLogger<string>('x', options);
+
+  for(let i = 0; i < 10; i += 1) {
+    // await new Promise(done => setTimeout(done, 2))
+    logger.info("what's the time mr wolf");
+  }
+
+  let last = 0;
+  logger._history.forEach(l => {
+    const { time } =  JSON.parse(l);
+    t.log(time)
+    t.true(time > last)
+    last = time;
+  })
+})
+
 test('print() should be barebones', (t) => {
   const options = { level: 'default' as const };
   const logger = createLogger('x', options);

packages/runtime/CHANGELOG.md

@@ -1,5 +1,13 @@
 # @openfn/runtime
 
+## 0.0.33
+
+### Patch Changes
+
+- Removed log line
+- Updated dependencies [ca701e8]
+  - @openfn/logger@0.0.19
+
 ## 0.0.32
 
 ### Patch Changes

packages/runtime/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@openfn/runtime",
-  "version": "0.0.32",
+  "version": "0.0.33",
   "description": "Job processing runtime.",
   "type": "module",
   "exports": {

packages/runtime/src/execute/expression.ts

@@ -48,7 +48,6 @@ export default (
 
       clearTimeout(tid);
       logger.debug('Expression complete!');
-      logger.debug(result);
 
       exeDuration = Date.now() - exeDuration;