refactor: saner logging

.changeset/healthy-keys-compete.md

@@ -0,0 +1,17 @@
+---
+"barnard59-core": major
+"barnard59": major
+---
+
+Improve logging
+
+1. Added `trace` and `verbose` levels
+2. Log pipeline debug info as `trace` (closes #149)
+3. Change the semantics of CLI `--verbose` flag
+   - default level (without flag) is `warn` 
+   - `-v` -> `info`
+   - `-vv` -> `debug`
+   - `-vvv` -> `verbose`
+   - `-vvvv` -> `trace`
+4. Added new `--quiet` flag to disable all logging
+5. Pipeline variables are logged to `verbose`

packages/cli/lib/cli.js

@@ -7,6 +7,7 @@ program
   .addOption(commonOptions.variable)
   .addOption(commonOptions.variableAll)
   .addOption(commonOptions.verbose)
+  .addOption(commonOptions.quiet)
   .addOption(monitoringOptions.enableBufferMonitor)
   .addOption(monitoringOptions.debug)
   .addOption(monitoringOptions.metricsExporter)
@@ -24,6 +25,7 @@ export default async function () {
     .addOption(commonOptions.variable)
     .addOption(commonOptions.variableAll)
     .addOption(commonOptions.verbose)
+    .addOption(commonOptions.quiet)
 
   await program.parseAsync(process.argv)
 }

packages/cli/lib/cli/commonOptions.js

@@ -19,3 +19,5 @@ export const variableAll = new Option('--variable-all', 'Import all environment
 export const verbose = new Option('-v, --verbose', 'enable diagnostic console output')
   .default(0)
   .argParser((v, total) => ++total)
+
+export const quiet = new Option('-q, --quiet', 'Disable all logging')

packages/cli/lib/cli/runAction.js

@@ -31,15 +31,14 @@ function createOutputStream(output) {
 }
 
 export default async function (filename, options = {}) {
-  const { output, pipeline: iri, variable: variables, variableAll, verbose, enableBufferMonitor } = {
+  const { output, pipeline: iri, variable: variables, variableAll, verbose, enableBufferMonitor, quiet } = {
     ...program.opts(),
     ...options,
   }
 
   await tracer.startActiveSpan('barnard59 run', async span => {
     try {
-      const level = ['error', 'info', 'debug', 'trace'][verbose] || 'error'
-
+      const level = ['warn', 'info', 'debug', 'verbose', 'trace'][verbose] || 'warn'
       const dataset = await fileToDataset(filename)
       const ptr = findPipeline(dataset, iri)
 
@@ -55,6 +54,7 @@ export default async function (filename, options = {}) {
       const { finished: runFinished, pipeline } = await runner(ptr, {
         basePath: resolve(dirname(filename)),
         level,
+        quiet,
         outputStream,
         variables,
       })

packages/cli/runner.js

@@ -2,11 +2,11 @@ import { createPipeline, defaultLogger, run } from 'barnard59-core'
 
 import tracer from './lib/tracer.js'
 
-function create(ptr, { basePath, outputStream, logger, variables = new Map(), level = 'error' } = {}) {
+function create(ptr, { basePath, outputStream, logger, variables = new Map(), level = 'error', quiet } = {}) {
   return tracer.startActiveSpan('createPipeline', { 'pipeline.id': ptr.value }, async span => {
     try {
       if (!logger) {
-        logger = defaultLogger({ level })
+        logger = defaultLogger({ level, quiet })
       }
 
       const pipeline = createPipeline(ptr, {

packages/cli/test/barnard59.test.js

@@ -31,39 +31,48 @@ describe('barnard59', function () {
 
     describe('verbose', () => {
       it('should log info messages if verbose flag is set', () => {
-        const pipelineFile = filenamePipelineDefinition('simple')
+        const pipelineFile = filenamePipelineDefinition('logs')
         const command = `${barnard59} run --pipeline=http://example.org/pipeline/ --verbose ${pipelineFile}`
 
+        const result = stripAnsi(shell.exec(command, { cwd }).stderr)
+
+        expect(result).to.match(/^info: /m)
+      })
+
+      it('all logs suppressed with --quiet flag', () => {
+        const pipelineFile = filenamePipelineDefinition('logs')
+        const command = `${barnard59} run --pipeline=http://example.org/pipeline/ --verbose ${pipelineFile} -q`
+
         const result = stripAnsi(shell.exec(command, { silent: true, cwd }).stderr)
 
-        strictEqual((/^info: /m).test(result), true)
+        expect(result).to.be.empty
       })
 
       it('should log info messages if verbose flag is set before command', () => {
-        const pipelineFile = filenamePipelineDefinition('simple')
+        const pipelineFile = filenamePipelineDefinition('logs')
         const command = `${barnard59} --verbose run --pipeline=http://example.org/pipeline/ ${pipelineFile}`
 
         const result = stripAnsi(shell.exec(command, { silent: true, cwd }).stderr)
 
-        strictEqual((/^info: /m).test(result), true)
+        expect(result).to.match(/^info: /m)
       })
 
       it('should not log debug messages if verbose flag is set', () => {
-        const pipelineFile = filenamePipelineDefinition('simple')
+        const pipelineFile = filenamePipelineDefinition('logs')
         const command = `${barnard59} run --pipeline=http://example.org/pipeline/ --verbose ${pipelineFile}`
 
         const result = stripAnsi(shell.exec(command, { silent: true, cwd }).stderr)
 
-        strictEqual((/^debug: /m).test(result), false)
+        expect(result).not.to.match(/^debug: /m)
       })
 
-      it('should log debug messages if verbose flag is set twice', () => {
-        const pipelineFile = filenamePipelineDefinition('simple')
-        const command = `${barnard59} run --pipeline=http://example.org/pipeline/ --verbose --verbose ${pipelineFile}`
+      it('should log trace messages if verbose flag is set 4 times', () => {
+        const pipelineFile = filenamePipelineDefinition('logs')
+        const command = `${barnard59} run --pipeline=http://example.org/pipeline/ -vvvv ${pipelineFile}`
 
         const result = stripAnsi(shell.exec(command, { silent: true, cwd }).stderr)
 
-        strictEqual((/^debug: /m).test(result), true)
+        expect(result).to.match(/^trace: /m)
       })
     })
 
@@ -104,7 +113,7 @@ describe('barnard59', function () {
         const result = stripAnsi(shell.exec(command, { silent: true }).stderr)
 
         expect(result).to.match(/info:.+abc: 123/)
-        expect(result).to.match(/debug:.+def: 456/)
+        expect(result).to.match(/verbose:.+def: 456/)
       })
 
       it('should import all environment variables before command', () => {
@@ -114,7 +123,7 @@ describe('barnard59', function () {
         const result = stripAnsi(shell.exec(command, { silent: true }).stderr)
 
         expect(result).to.match(/info:.+abc: 123/)
-        expect(result).to.match(/debug:.+def: 456/)
+        expect(result).to.match(/verbose:.+def: 456/)
       })
     })
   })

packages/cli/test/support/definitions/logs.ttl

@@ -0,0 +1,17 @@
+@base <http://example.org/pipeline/> .
+@prefix code: <https://code.described.at/> .
+@prefix p: <https://pipeline.described.at/> .
+@prefix rdf: <http://www.w3.org/1999/02/22-rdf-syntax-ns#> .
+
+<> a p:Pipeline, p:Readable ;
+  p:steps
+    [
+      p:stepList ( <read> )
+    ] .
+
+<read> a p:Step ;
+  code:implementedBy
+    [
+      a code:EcmaScriptModule ;
+      code:link <file:../operations/logs.js#default>
+    ] .

packages/cli/test/support/operations/logs.js

@@ -0,0 +1,17 @@
+import { Readable } from 'readable-stream'
+
+export default function () {
+  this.logger.trace('test trace')
+  this.logger.debug('test debug')
+  this.logger.verbose('test verbose')
+  this.logger.info('test info')
+  this.logger.warn('test warn')
+  this.logger.error('test error')
+
+  return new Readable({
+    read() {
+      this.push('')
+      this.push(null)
+    },
+  })
+}

packages/core/lib/Pipeline.js

@@ -26,7 +26,7 @@ class Pipeline extends StreamObject {
   }) {
     super({ basePath, children, context, loaderRegistry, logger, ptr, variables })
 
-    this.logger.debug({ iri: this.ptr.value, message: 'create new Pipeline' })
+    this.logger.trace({ iri: this.ptr.value, message: 'create new Pipeline' })
 
     this.readable = readable
     this.readableObjectMode = readableObjectMode
@@ -52,7 +52,7 @@ class Pipeline extends StreamObject {
 
     this._chunks = 0
 
-    this.logger.info({ iri: this.ptr.value, message: 'created new Pipeline' })
+    this.logger.trace({ iri: this.ptr.value, message: 'created new Pipeline' })
   }
 
   get firstChild() {
@@ -69,7 +69,7 @@ class Pipeline extends StreamObject {
   }
 
   async _init() {
-    this.logger.debug({ iri: this.ptr.value, message: 'initialize Pipeline' })
+    this.logger.trace({ iri: this.ptr.value, message: 'initialize Pipeline' })
 
     try {
       await this.onInit(this)
@@ -96,7 +96,7 @@ class Pipeline extends StreamObject {
       this.logger.error(err, { iri: this.ptr.value })
     }
 
-    this.logger.debug({ iri: this.ptr.value, message: 'initialized Pipeline' })
+    this.logger.trace({ iri: this.ptr.value, message: 'initialized Pipeline' })
   }
 
   destroy(err) {

packages/core/lib/Step.js

@@ -40,7 +40,7 @@ class Step extends StreamObject {
       stream.on(event, () => this._span.addEvent(event))
     }
 
-    this.logger.info({ iri: this.ptr.value, message: 'created new Step' })
+    this.logger.trace({ iri: this.ptr.value, message: 'created new Step' })
   }
 }
 

packages/core/lib/StreamObject.js

@@ -20,7 +20,7 @@ class StreamObject {
     this.variables = variables
     this.stream = stream
 
-    this.logger.debug({ iri: this.ptr.value, message: 'created new StreamObject' })
+    this.logger.trace({ iri: this.ptr.value, message: 'created new StreamObject' })
   }
 }
 

packages/core/lib/defaultLogger.js

@@ -3,12 +3,21 @@ import winston from 'winston'
 const { createLogger, format, transports } = winston
 const { Console, File } = transports
 
-function factory({ console = true, errorFilename = null, filename = null, level = 'error' } = {}) {
+const levels = {
+  error: 0,
+  warn: 1,
+  info: 2,
+  verbose: 3,
+  debug: 4,
+  trace: 5,
+}
+
+function factory({ console = true, errorFilename = null, filename = null, level = 'error', quiet } = {}) {
   const transports = []
 
   if (console) {
     transports.push(new Console({
-      consoleWarnLevels: ['warn', 'debug', 'log', 'info', 'error'],
+      consoleWarnLevels: Object.keys(levels),
       format: format.combine(
         format.colorize(),
         format.simple(),
@@ -24,7 +33,11 @@ function factory({ console = true, errorFilename = null, filename = null, level
     transports.push(new File({ filename }))
   }
 
+  winston.addColors({
+    trace: 'blue',
+  })
   return createLogger({
+    levels,
     level,
     format: format.combine(
       format.timestamp(),
@@ -33,6 +46,7 @@ function factory({ console = true, errorFilename = null, filename = null, level
       format.json(),
     ),
     transports,
+    silent: quiet,
   })
 }
 

packages/core/lib/factory/pipeline.js

@@ -64,7 +64,7 @@ function logVariables(ptr, logger, variables) {
   if (variables.size) {
     logger.info('variables in pipeline:', { iri: ptr.value })
     for (const [key, value] of variables) {
-      let level = 'debug'
+      let level = 'verbose'
       if (ptr.out(ns.p.variables).out(ns.p.variable).has(ns.p.name, key).term) {
         level = 'info'
       }

packages/core/test/factory/pipeline.test.js

@@ -117,6 +117,9 @@ describe('factory/pipeline', () => {
     const logger = {
       debug: sinon.spy(),
       info: sinon.spy(),
+      error: sinon.spy(),
+      trace: sinon.spy(),
+      verbose: sinon.spy(),
     }
 
     // when
@@ -130,6 +133,6 @@ describe('factory/pipeline', () => {
     // then
     expect(logger.info).to.have.been.calledWith(sinon.match(/foo: foo/))
     expect(logger.info).to.have.been.calledWith(sinon.match(/bar: \*\*\*/))
-    expect(logger.debug).to.have.been.calledWith(sinon.match(/baz: baz/))
+    expect(logger.verbose).to.have.been.calledWith(sinon.match(/baz: baz/))
   })
 })