From 274b9c8e81afd99931c6a4a767ff88da9a69aa2c Mon Sep 17 00:00:00 2001 From: tpluscode Date: Tue, 15 Aug 2023 12:27:21 +0200 Subject: [PATCH] refactor: saner logging --- .changeset/healthy-keys-compete.md | 17 ++++++++++ package-lock.json | 6 ++-- packages/cli/lib/cli.js | 2 ++ packages/cli/lib/cli/commonOptions.js | 2 ++ packages/cli/lib/cli/runAction.js | 6 ++-- packages/cli/runner.js | 4 +-- packages/cli/test/barnard59.test.js | 33 ++++++++++++------- .../cli/test/support/definitions/logs.ttl | 17 ++++++++++ packages/cli/test/support/operations/logs.js | 17 ++++++++++ packages/core/lib/Pipeline.js | 8 ++--- packages/core/lib/Step.js | 2 +- packages/core/lib/StreamObject.js | 2 +- packages/core/lib/defaultLogger.js | 18 ++++++++-- packages/core/lib/factory/pipeline.js | 2 +- packages/core/test/factory/pipeline.test.js | 5 ++- 15 files changed, 111 insertions(+), 30 deletions(-) create mode 100644 .changeset/healthy-keys-compete.md create mode 100644 packages/cli/test/support/definitions/logs.ttl create mode 100644 packages/cli/test/support/operations/logs.js diff --git a/.changeset/healthy-keys-compete.md b/.changeset/healthy-keys-compete.md new file mode 100644 index 00000000..c3c2007a --- /dev/null +++ b/.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` diff --git a/package-lock.json b/package-lock.json index 4be8462c..fa0369de 100644 --- a/package-lock.json +++ b/package-lock.json @@ -20316,7 +20316,7 @@ }, "packages/cli": { "name": "barnard59", - "version": "1.1.6", + "version": "1.1.7", "license": "MIT", "dependencies": { "@opentelemetry/api": "^1.0.0", @@ -20329,7 +20329,7 @@ "@opentelemetry/tracing": "^0.24.0", "@rdfjs/namespace": "^2.0.0", "@zazuko/env": "^1.0.1", - "barnard59-core": "2.1.1", + "barnard59-core": "2.1.2", "clownface": "^2.0.0", "commander": "^7.1.0", "lodash": "^4.17.21", @@ -20379,7 +20379,7 @@ }, "packages/core": { "name": "barnard59-core", - "version": "2.1.1", + "version": "2.1.2", "license": "MIT", "dependencies": { "@opentelemetry/api": "^1.0.1", diff --git a/packages/cli/lib/cli.js b/packages/cli/lib/cli.js index 55f81292..6b12a2af 100644 --- a/packages/cli/lib/cli.js +++ b/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) } diff --git a/packages/cli/lib/cli/commonOptions.js b/packages/cli/lib/cli/commonOptions.js index b5a8ba21..3dc3a493 100644 --- a/packages/cli/lib/cli/commonOptions.js +++ b/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') diff --git a/packages/cli/lib/cli/runAction.js b/packages/cli/lib/cli/runAction.js index 974da793..ab0f6497 100644 --- a/packages/cli/lib/cli/runAction.js +++ b/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, }) diff --git a/packages/cli/runner.js b/packages/cli/runner.js index 56067947..9be717ad 100644 --- a/packages/cli/runner.js +++ b/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, { diff --git a/packages/cli/test/barnard59.test.js b/packages/cli/test/barnard59.test.js index 137691a1..250b6010 100644 --- a/packages/cli/test/barnard59.test.js +++ b/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/) }) }) }) diff --git a/packages/cli/test/support/definitions/logs.ttl b/packages/cli/test/support/definitions/logs.ttl new file mode 100644 index 00000000..337d4561 --- /dev/null +++ b/packages/cli/test/support/definitions/logs.ttl @@ -0,0 +1,17 @@ +@base . +@prefix code: . +@prefix p: . +@prefix rdf: . + +<> a p:Pipeline, p:Readable ; + p:steps + [ + p:stepList ( ) + ] . + + a p:Step ; + code:implementedBy + [ + a code:EcmaScriptModule ; + code:link + ] . diff --git a/packages/cli/test/support/operations/logs.js b/packages/cli/test/support/operations/logs.js new file mode 100644 index 00000000..08bf3119 --- /dev/null +++ b/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) + }, + }) +} diff --git a/packages/core/lib/Pipeline.js b/packages/core/lib/Pipeline.js index 8611ee40..8fc39adc 100644 --- a/packages/core/lib/Pipeline.js +++ b/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) { diff --git a/packages/core/lib/Step.js b/packages/core/lib/Step.js index 2780f93c..20fdfd72 100644 --- a/packages/core/lib/Step.js +++ b/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' }) } } diff --git a/packages/core/lib/StreamObject.js b/packages/core/lib/StreamObject.js index 3d22dcdd..597e773d 100644 --- a/packages/core/lib/StreamObject.js +++ b/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' }) } } diff --git a/packages/core/lib/defaultLogger.js b/packages/core/lib/defaultLogger.js index 719135c7..a56056e5 100644 --- a/packages/core/lib/defaultLogger.js +++ b/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, }) } diff --git a/packages/core/lib/factory/pipeline.js b/packages/core/lib/factory/pipeline.js index 5f029dec..71778ae2 100644 --- a/packages/core/lib/factory/pipeline.js +++ b/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' } diff --git a/packages/core/test/factory/pipeline.test.js b/packages/core/test/factory/pipeline.test.js index d1914658..561513cf 100644 --- a/packages/core/test/factory/pipeline.test.js +++ b/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/)) }) })