Line-by-line logger (#4)

Updated default logger. Docs (from new readme): - Arrays will be logged line be line - For each line logged: - string, numbers and booleans are logged directly - objects are logged with `JSON.stringify(___, null, 2)` So if the procedure returns `['one', 'two', 'three]` this will be written to stdout: ``` one two three ``` If the procedure returns `[{name: 'one'}, {name: 'two'}, {name: 'three'}]` this will be written to stdout: ``` { "name": "one" } { "name": "two" } { "name": "three" } ``` This is to make it as easy as possible to use with other command line tools like `xargs`, `jq` etc. via bash-piping. If you don't want to rely on this logging, you can always log inside your procedures however you like and avoid returning a value. --------- Co-authored-by: Misha Kaletsky <[email protected]>
mmkal · May 26, 2024 · e48e0dd · e48e0dd
1 parent a25b005
commit e48e0dd
Show file tree

Hide file tree

Showing 6 changed files with 253 additions and 53 deletions.
diff --git a/README.md b/README.md
@@ -184,7 +184,7 @@ The above can be invoked with either `yarn` or `yarn install`.
 ### API docs
 
 <!-- codegen:start {preset: markdownFromJsdoc, source: src/index.ts, export: trpcCli} -->
-#### [trpcCli](./src/index.ts#L28)
+#### [trpcCli](./src/index.ts#L29)
 
 Run a trpc router as a CLI.
 
@@ -356,7 +356,40 @@ const appRouter = trpc.router({
 
 ## Output and lifecycle
 
-The output of the command will be logged via `console.info`. The process will exit with code 0 if the command was successful, or 1 otherwise. If you don't want to rely on this logging, you can always log inside your procedures and avoid returning a value. You can also override the `logger` and `process` properties of the `run` method:
+The output of the command will be logged if it is truthy. The log algorithm aims to be friendly for bash-piping, usage with jq etc.:
+
+- Arrays will be logged line be line
+- For each line logged:
+   - string, numbers and booleans are logged directly
+   - objects are logged with `JSON.stringify(___, null, 2)`
+
+So if the procedure returns `['one', 'two', 'three]` this will be written to stdout:
+
+```
+one
+two
+three
+```
+
+If the procedure returns `[{name: 'one'}, {name: 'two'}, {name: 'three'}]` this will be written to stdout:
+
+```
+{
+  "name": "one"
+}
+{
+  "name": "two"
+}
+{
+  "name": "three"
+}
+```
+
+This is to make it as easy as possible to use with other command line tools like `xargs`, `jq` etc. via bash-piping. If you don't want to rely on this logging, you can always log inside your procedures however you like and avoid returning a value.
+
+The process will exit with code 0 if the command was successful, or 1 otherwise. 
+
+You can also override the `logger` and `process` properties of the `run` method to change the default return-value logging and/or process.exit behaviour:
 
 <!-- eslint-disable unicorn/no-process-exit -->
 ```ts
@@ -365,7 +398,7 @@ import {trpcCli} from 'trpc-cli'
 const cli = trpcCli({router: yourRouter})
 
 cli.run({
-  logger: yourLogger, // needs `.info` and `.error` methods
+  logger: yourLogger, // should define `.info` and `.error` methods
   process: {
     exit: code => {
       if (code === 0) process.exit(0)

diff --git a/src/index.ts b/src/index.ts
@@ -6,7 +6,8 @@ import {ZodError} from 'zod'
 import {type JsonSchema7Type} from 'zod-to-json-schema'
 import * as zodValidationError from 'zod-validation-error'
 import {flattenedProperties, incompatiblePropertyPairs, getDescription} from './json-schema'
-import {TrpcCliParams} from './types'
+import {lineByLineConsoleLogger} from './logging'
+import {Logger, TrpcCliParams} from './types'
 import {parseProcedureInputs} from './zod-procedure'
 
 export * from './types'
@@ -50,12 +51,8 @@ export const trpcCli = <R extends AnyRouter>({router, ...params}: TrpcCliParams<
     procedures.flatMap(([k, v]) => (typeof v === 'string' ? [[k, v] as const] : [])),
   )
 
-  async function run(runParams?: {
-    argv?: string[]
-    logger?: {info?: (...args: unknown[]) => void; error?: (...args: unknown[]) => void}
-    process?: {exit: (code: number) => never}
-  }) {
-    const logger = {...console, ...runParams?.logger}
+  async function run(runParams?: {argv?: string[]; logger?: Logger; process?: {exit: (code: number) => never}}) {
+    const logger = {...lineByLineConsoleLogger, ...runParams?.logger}
     const _process = runParams?.process || process
     let verboseErrors: boolean = false
 

diff --git a/src/logging.ts b/src/logging.ts
@@ -0,0 +1,45 @@
+import {Log, Logger} from './types'
+
+export const lineByLineLogger = getLoggerTransformer(log => {
+  /**
+   * @param args values to log. if `logger.info('a', 1)` is called, `args` will be `['a', 1]`
+   * @param depth tracks whether the current call recursive. Used to make sure we don't flatten nested arrays
+   */
+  const wrapper = (args: unknown[], depth: number) => {
+    if (args.length === 1 && Array.isArray(args[0]) && depth === 0) {
+      args[0].forEach(item => wrapper([item], 1))
+    } else if (args.every(isPrimitive)) {
+      log(...args)
+    } else if (args.length === 1) {
+      log(JSON.stringify(args[0], null, 2))
+    } else {
+      log(JSON.stringify(args, null, 2))
+    }
+  }
+
+  return (...args) => wrapper(args, 0)
+})
+
+const isPrimitive = (value: unknown): value is string | number | boolean => {
+  const type = typeof value
+  return type === 'string' || type === 'number' || type === 'boolean'
+}
+
+/** Takes a function that wraps an individual log function, and returns a function that wraps the `info` and `error` functions for a logger */
+function getLoggerTransformer(transform: (log: Log) => Log) {
+  return (logger: Logger): Logger => {
+    const info = logger.info && transform(logger.info)
+    const error = logger.error && transform(logger.error)
+    return {info, error}
+  }
+}
+
+/**
+ * A logger which uses `console.log` and `console.error` to log in the following way:
+ * - Primitives are logged directly
+ * - Arrays are logged item-by-item
+ * - Objects are logged as JSON
+ *
+ * This is useful for logging structured data in a human-readable way, and for piping logs to other tools.
+ */
+export const lineByLineConsoleLogger = lineByLineLogger(console)
diff --git a/src/types.ts b/src/types.ts
@@ -48,7 +48,19 @@ export interface ParsedProcedure {
    * Function for taking cleye parsed argv output and transforming it so it can be passed into the procedure
    * Needed because this function is where inspect the input schema(s) and determine how to map the argv to the input
    */
-  getInput: (argv: {_: string[]; flags: {}}) => unknown
+  getInput: (argv: {_: string[]; flags: Record<string, unknown>}) => unknown
 }
 
 export type Result<T> = {success: true; value: T} | {success: false; error: string}
+
+/** A function that logs any inputs. e.g. `console.info` */
+export type Log = (...args: unknown[]) => void
+
+/**
+ * A struct which has `info` and `error` functions for logging. Easiest example: `console`
+ * But most loggers like pino, winston etc. have a similar interface.
+ */
+export interface Logger {
+  info?: Log
+  error?: Log
+}
diff --git a/test/e2e.test.ts b/test/e2e.test.ts
@@ -2,6 +2,7 @@ import {execa} from 'execa'
 import * as path from 'path'
 import stripAnsi from 'strip-ansi'
 import {expect, test} from 'vitest'
+import '../src' // make sure vitest reruns this file after every change
 
 const tsx = async (file: string, args: string[]) => {
   const {all} = await execa('./node_modules/.bin/tsx', ['test/fixtures/' + file, ...args], {
@@ -134,25 +135,21 @@ test('migrations union type', async () => {
   let output = await tsx('migrations', ['apply', '--to', 'four'])
 
   expect(output).toMatchInlineSnapshot(`
-    "[
-      'one: executed',
-      'two: executed',
-      'three: executed',
-      'four: executed',
-      'five: pending'
-    ]"
+    "one: executed
+    two: executed
+    three: executed
+    four: executed
+    five: pending"
   `)
 
   output = await tsx('migrations', ['apply', '--step', '1'])
   expect(output).toContain('four: pending') // <-- this sometimes goes wrong when I mess with union type handling
   expect(output).toMatchInlineSnapshot(`
-    "[
-      'one: executed',
-      'two: executed',
-      'three: executed',
-      'four: pending',
-      'five: pending'
-    ]"
+    "one: executed
+    two: executed
+    three: executed
+    four: pending
+    five: pending"
   `)
 })
 
@@ -177,36 +174,32 @@ test('migrations search.byName help', async () => {
 test('migrations search.byName', async () => {
   const output = await tsx('migrations', ['search.byName', '--name', 'two'])
   expect(output).toMatchInlineSnapshot(`
-    "[
-      {
-        name: 'two',
-        content: 'create view two as select name from one',
-        status: 'executed'
-      }
-    ]"
+    "{
+      "name": "two",
+      "content": "create view two as select name from one",
+      "status": "executed"
+    }"
   `)
 })
 
 test('migrations search.byContent', async () => {
   const output = await tsx('migrations', ['search.byContent', '--searchTerm', 'create table'])
   expect(output).toMatchInlineSnapshot(`
-    "[
-      {
-        name: 'one',
-        content: 'create table one(id int, name text)',
-        status: 'executed'
-      },
-      {
-        name: 'three',
-        content: 'create table three(id int, foo int)',
-        status: 'pending'
-      },
-      {
-        name: 'five',
-        content: 'create table five(id int)',
-        status: 'pending'
-      }
-    ]"
+    "{
+      "name": "one",
+      "content": "create table one(id int, name text)",
+      "status": "executed"
+    }
+    {
+      "name": "three",
+      "content": "create table three(id int, foo int)",
+      "status": "pending"
+    }
+    {
+      "name": "five",
+      "content": "create table five(id int)",
+      "status": "pending"
+    }"
   `)
 })
 
@@ -261,16 +254,48 @@ test('fs copy help', async () => {
 
 test('fs copy', async () => {
   expect(await tsx('fs', ['copy', 'one'])).toMatchInlineSnapshot(
-    `"{ source: 'one', destination: 'one.copy', options: { force: false } }"`,
+    `
+      "{
+        "source": "one",
+        "destination": "one.copy",
+        "options": {
+          "force": false
+        }
+      }"
+    `,
   )
   expect(await tsx('fs', ['copy', 'one', 'uno'])).toMatchInlineSnapshot(
-    `"{ source: 'one', destination: 'uno', options: { force: false } }"`,
+    `
+      "{
+        "source": "one",
+        "destination": "uno",
+        "options": {
+          "force": false
+        }
+      }"
+    `,
   )
   expect(await tsx('fs', ['copy', 'one', '--force'])).toMatchInlineSnapshot(
-    `"{ source: 'one', destination: 'one.copy', options: { force: true } }"`,
+    `
+      "{
+        "source": "one",
+        "destination": "one.copy",
+        "options": {
+          "force": true
+        }
+      }"
+    `,
   )
   expect(await tsx('fs', ['copy', 'one', 'uno', '--force'])).toMatchInlineSnapshot(
-    `"{ source: 'one', destination: 'uno', options: { force: true } }"`,
+    `
+      "{
+        "source": "one",
+        "destination": "uno",
+        "options": {
+          "force": true
+        }
+      }"
+    `,
   )
 
   // invalid enum value:

diff --git a/test/logging.test.ts b/test/logging.test.ts
@@ -0,0 +1,88 @@
+import {beforeEach, expect, test, vi} from 'vitest'
+import {lineByLineLogger} from '../src/logging'
+
+const info = vi.fn()
+const error = vi.fn()
+const mocks = {info, error}
+const jsonish = lineByLineLogger(mocks)
+
+beforeEach(() => {
+  vi.clearAllMocks()
+})
+
+expect.addSnapshotSerializer({
+  test: val => val.mock.calls,
+  print: (val: any) => val.mock.calls.map((call: unknown[]) => call.join(' ')).join('\n'),
+})
+
+test('logging', async () => {
+  jsonish.info!('Hello', 'world')
+
+  expect(info).toMatchInlineSnapshot(`Hello world`)
+})
+
+test('string array', async () => {
+  jsonish.info!(['m1', 'm2', 'm3'])
+
+  expect(info).toMatchInlineSnapshot(`
+    m1
+    m2
+    m3
+  `)
+})
+
+test('primitives array', async () => {
+  jsonish.info!(['m1', 'm2', 11, true, 'm3'])
+
+  expect(info).toMatchInlineSnapshot(`
+    m1
+    m2
+    11
+    true
+    m3
+  `)
+})
+
+test('array array', async () => {
+  jsonish.info!([
+    ['m1', 'm2'],
+    ['m3', 'm4'],
+  ])
+
+  expect(info).toMatchInlineSnapshot(`
+    [
+      "m1",
+      "m2"
+    ]
+    [
+      "m3",
+      "m4"
+    ]
+  `)
+})
+
+test('multi primitives', async () => {
+  jsonish.info!('m1', 11, true, 'm2')
+  jsonish.info!('m1', 12, false, 'm2')
+
+  expect(info).toMatchInlineSnapshot(`
+    m1 11 true m2
+    m1 12 false m2
+  `)
+})
+
+test('object array', async () => {
+  jsonish.info!([{name: 'm1'}, {name: 'm2'}, {name: 'm3'}])
+
+  expect(info).toMatchInlineSnapshot(`
+    {
+      "name": "m1"
+    }
+    {
+      "name": "m2"
+    }
+    {
+      "name": "m3"
+    }
+  `)
+})