Merge pull request #159 from OpenFn/log-json

Logger: output as JSON

.changeset/good-snails-fail.md

@@ -0,0 +1,6 @@
+---
+'@openfn/cli': patch
+'@openfn/logger': patch
+---
+
+Support logging to JSON

.changeset/pretty-terms-refuse.md

@@ -0,0 +1,5 @@
+---
+'@openfn/runtime': patch
+---
+
+serialize job errors

packages/cli/README.md

@@ -91,6 +91,16 @@ If something unexpected happens during a command, your first step should be to r
 
 `debug` level logging is highly verbose and aims to tell you everything that's going on under-the hood. This is aimed mostly at CLI/runtime developers and can be very useful for debugging problems.
 
+## Structred/JSON logging
+
+By default all logs will be printed as human-readable strings.
+
+For a more structured output, you can emit logs as JSON objects with `level`, `name` and `message` properties:
+```
+{ level: 'info', name: 'CLI', message: ['Loaded adaptor'] }
+```
+
+Pass `--log-json` to the CLI to do this. You can also set the OPENFN_LOG_JSON env var (and use `--no-log-json` to disable).
 
 ## Compilation
 

packages/cli/src/cli.ts

@@ -23,6 +23,10 @@ export const cmd = yargs(hideBin(process.argv))
     description: 'Set the default log level to none, default, info or debug',
     array: true,
   })
+  .option('log-json', {
+    description: 'Output all logs as JSON objects',
+    boolean: true,
+  })
   .example('openfn execute help', 'Show documentation for the execute command')
   .example(
     'openfn docs @openfn/language-common each',

packages/cli/src/commands.ts

@@ -32,6 +32,7 @@ export type Opts = {
   immutable?: boolean;
   jobPath?: string;
   log?: string[];
+  logJson?: boolean;
   noCompile?: boolean;
   strictOutput?: boolean; // defaults to true
   outputPath?: string;
@@ -56,7 +57,8 @@ const handlers = {
   ['repo-install']: install,
   ['repo-pwd']: pwd,
   ['repo-list']: list,
-  version: async (_opts: SafeOpts, logger: Logger) => printVersions(logger),
+  version: async (opts: SafeOpts, logger: Logger) =>
+    printVersions(logger, opts),
 };
 
 export type SafeOpts = Required<Omit<Opts, 'log' | 'adaptor'>> & {

packages/cli/src/util/ensure-opts.ts

@@ -78,19 +78,23 @@ export default function ensureOpts(
     adaptors: opts.adaptors || [],
     autoinstall: opts.autoinstall,
     command: opts.command,
+    expand: opts.expand !== false,
     force: opts.force || false,
-    repoDir: opts.repoDir || process.env.OPENFN_REPO_DIR || DEFAULT_REPO_DIR,
+    immutable: opts.immutable || false,
+    logJson:
+      typeof opts.logJson == 'boolean'
+        ? opts.logJson
+        : Boolean(process.env.OPENFN_LOG_JSON),
     noCompile: Boolean(opts.noCompile),
-    expand: opts.expand !== false,
-    outputStdout: Boolean(opts.outputStdout),
     operation: opts.operation,
+    outputStdout: Boolean(opts.outputStdout),
     packages: opts.packages,
-    stateStdin: opts.stateStdin,
-    timeout: opts.timeout,
+    repoDir: opts.repoDir || process.env.OPENFN_REPO_DIR || DEFAULT_REPO_DIR,
+    skipAdaptorValidation: opts.skipAdaptorValidation ?? false,
     specifier: opts.specifier,
+    stateStdin: opts.stateStdin,
     strictOutput: opts.strictOutput ?? true,
-    skipAdaptorValidation: opts.skipAdaptorValidation ?? false,
-    immutable: opts.immutable || false,
+    timeout: opts.timeout,
   } as SafeOpts;
   const set = (key: keyof Opts, value: string) => {
     // @ts-ignore TODO

packages/cli/src/util/logger.ts

@@ -20,10 +20,13 @@ const namespaces: Record<string, string> = {
 
 export const createLogger = (
   name: string = '',
-  options: Pick<SafeOpts, 'log'>
+  options: Partial<Pick<SafeOpts, 'log' | 'logJson'>>
 ) => {
-  const logOptions = options.log || {};
+  const logOptions = options.log || { json: true };
   let level = logOptions[name] || logOptions.default || 'default';
+  if (options.logJson) {
+    logOptions.json = true;
+  }
   return actualCreateLogger(namespaces[name] || name, {
     level,
     ...logOptions,

packages/cli/src/util/print-versions.ts

@@ -1,13 +1,14 @@
 import { Logger } from './logger';
 import { mainSymbols } from 'figures';
+import { Opts } from '../commands';
 import { SafeOpts } from '../commands';
 import { getNameAndVersion } from '@openfn/runtime';
 
 const { triangleRightSmall: t } = mainSymbols;
 
 const printVersions = async (
   logger: Logger,
-  options: Partial<Pick<SafeOpts, 'adaptors'>> = {}
+  options: Partial<Pick<SafeOpts, 'adaptors' | 'logJson'>> = {}
 ) => {
   // Prefix and pad version numbers
   const prefix = (str: string) =>
@@ -20,20 +21,42 @@ const printVersions = async (
   const runtimeVersion = dependencies['@openfn/runtime'];
 
   const { adaptors } = options;
-  let adaptorVersionString = '';
+  let adaptorName, adaptorVersion;
   if (adaptors && adaptors.length === 1) {
     const [a] = adaptors;
     const { name, version } = getNameAndVersion(a);
-    adaptorVersionString = `\n${prefix(
-      'adaptor ' + name.replace(/^@openfn\/language-/, '')
-    )}${version || 'latest'}`;
+    adaptorName = name.replace(/^@openfn\/language-/, '');
+    adaptorVersion = version || 'latest';
   }
 
-  logger.info(`Versions:
+  let output: any;
+  if (options.logJson) {
+    output = {
+      versions: {
+        'node.js': process.version.substring(1),
+        cli: version,
+        runtime: runtimeVersion,
+        compiler: compilerVersion,
+      },
+    };
+    if (adaptorName) {
+      output.versions.adaptor = {
+        name: adaptorName,
+        version: adaptorVersion,
+      };
+    }
+  } else {
+    const adaptorVersionString = adaptorName
+      ? `\n${prefix('adaptor ' + adaptorName)}${adaptorVersion}`
+      : '';
+
+    output = `Versions:
 ${prefix('node.js')}${process.version.substring(1)}
 ${prefix('cli')}${version}
 ${prefix('runtime')}${runtimeVersion}
-${prefix('compiler')}${compilerVersion}${adaptorVersionString}`);
+${prefix('compiler')}${compilerVersion}${adaptorVersionString}`;
+  }
+  logger.info(output);
 };
 
 export default printVersions;

packages/cli/test/util/ensure-opts.test.ts

@@ -186,6 +186,40 @@ test('preserve expand', (t) => {
   t.false(opts.expand);
 });
 
+test('preserve logJson', (t) => {
+  const initialOpts = {
+    logJson: true,
+  } as Opts;
+
+  const opts = ensureOpts('a', initialOpts);
+
+  t.true(opts.logJson);
+});
+
+test('default logJson to true if env var is set', (t) => {
+  process.env.OPENFN_LOG_JSON = 'true';
+
+  const initialOpts = {} as Opts;
+
+  const opts = ensureOpts('a', initialOpts);
+
+  t.true(opts.logJson);
+  delete process.env.OPENFN_LOG_JSON;
+});
+
+test('logJson argument overrides env var', (t) => {
+  process.env.OPENFN_LOG_JSON = 'true';
+
+  const initialOpts = {
+    logJson: false,
+  } as Opts;
+
+  const opts = ensureOpts('a', initialOpts);
+
+  t.false(opts.logJson);
+  delete process.env.OPENFN_LOG_JSON;
+});
+
 test('preserve specifier', (t) => {
   const initialOpts = {
     specifier: '@openfn/language-common@1.0.0',

packages/logger/README.md

@@ -22,6 +22,13 @@ info    - For power users. Shows everything default plus generally interesting h
 debug   - For devs debugging - really detailed output about stepping into and out of major operations. Includes data dumps.
 none    - don't show any log output
 
+## JSON Output
+
+Set the `json` object to a truthy value to output all logs as JSON objects of the following structure:
+```
+{ level: 'info', name: 'CLI', message: ['Loaded adaptor'] }
+```
+
 ## Usage
 
 Import and create a logger:

packages/logger/package.json

@@ -29,6 +29,7 @@
   "dependencies": {
     "@inquirer/confirm": "0.0.28-alpha.0",
     "chalk": "^5.1.2",
+    "fast-safe-stringify": "^2.1.1",
     "figures": "^5.0.0"
   },
   "devDependencies": {

packages/logger/src/logger.ts

@@ -1,5 +1,6 @@
 import c from 'chalk';
 import iconfirm from '@inquirer/confirm';
+import stringify from 'fast-safe-stringify';
 import * as symbols from './symbols';
 import sanitize from './sanitize';
 import getDurationString from './util/duration';
@@ -30,9 +31,17 @@ export const WARN = 'warn';
 export type LogArgs = any[];
 
 // TODO something is wrong with these typings
-// Trying to differntite user priority presets from log functions
+// Trying to differentiate user priority presets from log functions
 export type LogFns = 'debug' | 'info' | 'log' | 'warn' | 'error' | 'success';
 
+export type JSONLog = {
+  message: Array<string | object | any>;
+  level: LogFns;
+  name?: string;
+};
+
+export type StringLog = [LogFns | 'confirm' | 'print', ...any];
+
 // Design for a logger
 // some inputs:
 // This will be passed into a job, so must look like the console object
@@ -117,39 +126,49 @@ export default function (name?: string, options: LogOptions = {}): Logger {
   // This is what we actually pass the log strings to
   const emitter = opts.logger;
 
-  // main logger function
   const log = (level: LogFns, ...args: LogArgs) => {
-    if (opts.level === NONE) return;
-
-    const output = [];
-
-    if (name && !opts.hideNamespace) {
-      // TODO how can we fix the with of the type column so that things
-      //      are nicely arranged in the CLI?
-      output.push(c.blue(`[${name}]`));
-    }
-    if (!opts.hideIcons) {
-      output.push(styleLevel(level));
+    if (priority[level] >= minLevel) {
+      if (options.json) {
+        logJSON(level, ...args);
+      } else {
+        logString(level, ...args);
+      }
     }
+  };
+
+  const logJSON = (level: LogFns, ...args: LogArgs) => {
+    const output: JSONLog = {
+      level,
+      name,
+      message: args.map((o) => sanitize(o, { stringify: false })),
+    };
 
-    output.push(...args);
-    // concatenate consecutive strings
-    // log objects by themselves, pretty printed
+    emitter[level](stringify(output));
+  };
 
-    // TODO I'd really really like a nice way to visualise log('state': hugeJsonObject)
-    // This will take some effort I think
+  const logString = (level: LogFns, ...args: LogArgs) => {
+    if (emitter.hasOwnProperty(level)) {
+      const output = [];
 
-    // how do we actually log?
-    if (priority[level] >= minLevel) {
-      if (emitter.hasOwnProperty(level)) {
-        const cleaned = output.map((o) => sanitize(o, options));
-        emitter[level](...cleaned);
+      if (name && !opts.hideNamespace) {
+        // TODO how can we fix the with of the type column so that things
+        //      are nicely arranged in the CLI?
+        output.push(c.blue(`[${name}]`));
       }
+      if (!opts.hideIcons) {
+        output.push(styleLevel(level));
+      }
+
+      output.push(...args);
+
+      const cleaned = output.map((o) => sanitize(o, options));
+      emitter[level](...cleaned);
     }
   };
 
   // print() will log without any metadata/overhead/santization
   // basically a proxy for console.log
+  // TODO should this use json?
   const print = (...args: any[]) => {
     if (opts.level !== NONE) {
       emitter.info(...args);