feat: allow to observe logs at runtime

This adds a log observer which receives logs created
from Features, Scenarios and Steps immediately

examples/mars-rover/tests.ts

@@ -1,10 +1,19 @@
+import chalk from 'chalk'
 import path from 'path'
 import { runFolder } from '../../runner/runFolder.js'
 import { RoverContext, steps } from './steps.js'
 
 const runner = await runFolder<RoverContext>({
 	folder: path.join(process.cwd(), 'examples', 'mars-rover'),
 	name: 'Mars Rover',
+	logObserver: {
+		onProgress: ({ ts }, ...progress) =>
+			console.error(
+				chalk.gray(`»`),
+				chalk.cyan(`@${ts}`),
+				...progress.map((s) => chalk.yellow(s)),
+			),
+	},
 })
 
 runner.addStepRunners(...steps)

runner/logger.spec.ts

@@ -1,10 +1,13 @@
 import assert from 'assert/strict'
 import { describe, it } from 'node:test'
+import { Step } from '../parser/grammar.js'
 import { LogEntry, logger, LogLevel } from './logger.js'
 
 describe('logger()', () => {
 	describe('should allow to log messages', () => {
-		const { progress, debug, error, getLogs, info } = logger({
+		const step = {} as Step
+		const { progress, debug, error, getLogs, info, context } = logger({
+			context: step ,
 			getRelativeTs: () => 42,
 		})
 		const expected: LogEntry[] = []
@@ -55,5 +58,52 @@ describe('logger()', () => {
 
 			assert.deepEqual(getLogs(), expected)
 		})
+
+		describe('context provides the source of the log', () => {
+			it('should provide the context', () => assert.equal(context, step))
+		})
+	})
+
+	describe('listening to logs', () => {
+		it('should call log listeners', () => {
+			const debugLogs: any[] = []
+			const infoLogs: any[] = []
+			const progressLogs: any[] = []
+			const errorLogs: any[] = []
+			const step = {} as Step
+			const l = logger({
+				context: step,
+				getRelativeTs: () => 42,
+				onDebug: (...args) => debugLogs.push(args),
+				onInfo: (...args) => infoLogs.push(args),
+				onProgress: (...args) => progressLogs.push(args),
+				onError: (...args) => errorLogs.push(args),
+			})
+
+			l.debug('foo', 'bar')
+			assert.deepEqual(debugLogs, [
+				[{ context: step, ts: 42, level: LogLevel.DEBUG }, 'foo', 'bar'],
+			])
+
+			l.info('bar', 'foo')
+			assert.deepEqual(infoLogs, [
+				[{ context: step, ts: 42, level: LogLevel.INFO }, 'bar', 'foo'],
+			])
+
+			l.progress('progress', 'foo')
+			assert.deepEqual(progressLogs, [
+				[
+					{ context: step, ts: 42, level: LogLevel.PROGRESS },
+					'progress',
+					'foo',
+				],
+			])
+
+			const e = new Error()
+			l.error(e)
+			assert.deepEqual(errorLogs, [
+				[{ context: step, ts: 42, level: LogLevel.ERROR }, e],
+			])
+		})
 	})
 })

runner/logger.ts

@@ -1,8 +1,26 @@
-export type Logger = {
+import { Feature, Scenario, Step } from '../parser/grammar.js'
+
+export type Logger<Context extends Feature | Scenario | Step> = {
+	/**
+	 * Logs a debug message
+	 */
 	debug: (...args: string[]) => void
+	/**
+	 * Logs a info message
+	 */
 	info: (...args: string[]) => void
+	/**
+	 * Logs a error message
+	 */
 	error: (error: ErrorInfo) => void
+	/**
+	 * Logs a progress message
+	 */
 	progress: (...args: string[]) => void
+	/**
+	 * Returns the context of the logger.
+	 */
+	context: Context
 }
 
 type ErrorInfo = {
@@ -26,37 +44,87 @@ export type LogEntry = {
 	ts: number
 }
 
-export const logger = ({
+type LogObserverInfo = {
+	context: Feature | Scenario | Step
+	level: LogLevel
+	/**
+	 * Time in ms from beginning of the feature run when the log message was created
+	 */
+	ts: number
+}
+
+export type LogObserver = {
+	/**
+	 * Register a listener that receives debug logs
+	 */
+	onDebug?: (info: LogObserverInfo, ...args: string[]) => unknown
+	/**
+	 * Register a listener that receives info logs
+	 */
+	onInfo?: (info: LogObserverInfo, ...args: string[]) => unknown
+	/**
+	 * Register a listener that receives error logs
+	 */
+	onError?: (info: LogObserverInfo, error: ErrorInfo) => unknown
+	/**
+	 * Register a listener that receives progress logs
+	 */
+	onProgress?: (info: LogObserverInfo, ...args: string[]) => unknown
+}
+
+export const logger = <Context extends Feature | Scenario | Step>({
+	context,
 	getRelativeTs,
+	onDebug,
+	onError,
+	onInfo,
+	onProgress,
 }: {
+	/**
+	 * The context the logs of this logger are coming from
+	 */
+	context: Context
+	/**
+	 * Returns the number of milliseconds that have elapse since the "start" of the test run.
+	 */
 	getRelativeTs: () => number
-}): Logger & { getLogs: () => LogEntry[] } => {
+} & LogObserver): Logger<Context> & { getLogs: () => LogEntry[] } => {
 	const logs: LogEntry[] = []
+	const ts = getRelativeTs()
 	return {
-		debug: (...message) =>
+		debug: (...message) => {
 			logs.push({
 				message,
 				level: LogLevel.DEBUG,
-				ts: getRelativeTs(),
-			}),
-		progress: (...message) =>
+				ts,
+			})
+			onDebug?.({ context, ts, level: LogLevel.DEBUG }, ...message)
+		},
+		progress: (...message) => {
 			logs.push({
 				message,
 				level: LogLevel.PROGRESS,
-				ts: getRelativeTs(),
-			}),
-		info: (...message) =>
+				ts,
+			})
+			onProgress?.({ context, ts, level: LogLevel.PROGRESS }, ...message)
+		},
+		info: (...message) => {
 			logs.push({
 				message,
 				level: LogLevel.INFO,
-				ts: getRelativeTs(),
-			}),
-		error: (error) =>
+				ts,
+			})
+			onInfo?.({ context, ts, level: LogLevel.INFO }, ...message)
+		},
+		error: (error) => {
 			logs.push({
 				message: [error.message],
 				level: LogLevel.ERROR,
-				ts: getRelativeTs(),
-			}),
+				ts,
+			})
+			onError?.({ context, ts, level: LogLevel.ERROR }, error)
+		},
 		getLogs: () => logs,
+		context,
 	}
 }

runner/runFeature.spec.ts

@@ -176,4 +176,52 @@ describe('runFeature()', () => {
 			},
 		])
 	})
+
+	describe('observe logs', () => {
+		it('should allow to pass a log observer', async () => {
+			const observedLogs: any[] = []
+			const featureResult = await runFeature({
+				stepRunners: [
+					async ({
+						log: {
+							feature: { debug, error, info, progress },
+						},
+					}) => {
+						debug(`A debug message`, `with two parts`)
+						error({ message: `Some error` })
+						info(`An info`)
+						progress(`Doing something`, `the thing`)
+					},
+				],
+				feature: (
+					await loadFeatureFile(
+						path.join(
+							process.cwd(),
+							'runner',
+							'test-data',
+							'runFeature',
+							'OneStep.feature.md',
+						),
+					)
+				).feature,
+				context: {},
+				getRelativeTs: () => 42,
+				logObserver: {
+					onDebug: (_, ...args) => observedLogs.push([LogLevel.DEBUG, ...args]),
+					onError: (_, error) => observedLogs.push([LogLevel.ERROR, error]),
+					onInfo: (_, ...args) => observedLogs.push([LogLevel.INFO, ...args]),
+					onProgress: (_, ...args) =>
+						observedLogs.push([LogLevel.PROGRESS, ...args]),
+				},
+			})
+
+			assert.equal(featureResult.ok, true)
+			assert.deepEqual(observedLogs, [
+				[LogLevel.DEBUG, `A debug message`, `with two parts`],
+				[LogLevel.ERROR, { message: `Some error` }],
+				[LogLevel.INFO, `An info`],
+				[LogLevel.PROGRESS, `Doing something`, `the thing`],
+			])
+		})
+	})
 })

runner/runFeature.ts

@@ -1,5 +1,5 @@
 import { Feature, Keyword, Row, Scenario } from '../parser/grammar.js'
-import { LogEntry, logger } from './logger.js'
+import { LogEntry, logger, LogObserver } from './logger.js'
 import { replaceFromExamples } from './replaceFromExamples.js'
 import { runScenario, ScenarioResult } from './runScenario.js'
 import { StepRunner } from './runStep.js'
@@ -21,17 +21,22 @@ export const runFeature = async <Context extends Record<string, any>>({
 	feature,
 	context,
 	getRelativeTs,
+	logObserver,
 }: {
 	stepRunners: StepRunner<Context>[]
 	feature: Feature
 	context: Context
 	getRelativeTs?: () => number
+	logObserver?: LogObserver
 }): Promise<FeatureResult> => {
 	const scenarioResults: [ScenarioExecution, ScenarioResult][] = []
 	const startTs = Date.now()
 	const relTs = getRelativeTs ?? (() => Date.now() - startTs)
-	const featureLogger = logger({ getRelativeTs: relTs })
-
+	const featureLogger = logger({
+		getRelativeTs: relTs,
+		context: feature,
+		...logObserver,
+	})
 	let aborted = false
 	for (const scenario of feature.scenarios) {
 		if (scenario.keyword === Keyword.ScenarioOutline) {
@@ -96,6 +101,7 @@ export const runFeature = async <Context extends Record<string, any>>({
 				context,
 				getRelativeTs: relTs,
 				featureLogger,
+				logObserver,
 			})
 			scenarioResults.push([
 				scenario as ScenarioExecution,

runner/runFolder.ts

@@ -1,9 +1,11 @@
+import { LogObserver } from './logger.js'
 import { parseFeaturesInFolder } from './parseFeaturesInFolder.js'
 import { Runner, runSuite } from './runSuite.js'
 
 export const runFolder = async <Context extends Record<string, any>>({
 	folder,
 	name,
+	logObserver,
 }: {
 	/**
 	 * The name for the test suite
@@ -13,5 +15,9 @@ export const runFolder = async <Context extends Record<string, any>>({
 	 * A path to a folder to load the features from
 	 */
 	folder: string
+	/**
+	 * Observe logs while they are being emitted
+	 */
+	logObserver?: LogObserver
 }): Promise<Runner<Context>> =>
-	runSuite<Context>(await parseFeaturesInFolder(folder), name)
+	runSuite<Context>(await parseFeaturesInFolder(folder), name, logObserver)

runner/runScenario.spec.ts

@@ -33,7 +33,7 @@ describe('runScenario()', () => {
 			scenario: feature.scenarios[0] as Scenario,
 			context: {},
 			getRelativeTs: getRelativeTs,
-			featureLogger: logger({ getRelativeTs }),
+			featureLogger: logger({ getRelativeTs, context: feature }),
 		}
 	})
 
@@ -138,7 +138,7 @@ describe('runScenario()', () => {
 			scenario: feature.scenarios[0] as Scenario,
 			context: {},
 			getRelativeTs: getRelativeTs,
-			featureLogger: logger({ getRelativeTs }),
+			featureLogger: logger({ getRelativeTs, context: feature }),
 		})
 
 		assert.equal(scenarioResult.ok, true)

runner/runScenario.ts

@@ -1,5 +1,5 @@
 import { Feature, Scenario, Step } from '../parser/grammar.js'
-import { LogEntry, logger, Logger } from './logger.js'
+import { LogEntry, logger, Logger, LogObserver } from './logger.js'
 import { runStep, StepResult, StepRunner } from './runStep.js'
 
 export type ScenarioResult = {
@@ -17,16 +17,22 @@ export const runScenario = async <Context extends Record<string, any>>({
 	context,
 	getRelativeTs,
 	featureLogger,
+	logObserver,
 }: {
 	stepRunners: StepRunner<Context>[]
 	feature: Feature
 	scenario: Scenario
 	context: Context
-	featureLogger: Logger
+	featureLogger: Logger<Feature>
 	getRelativeTs: () => number
+	logObserver?: LogObserver
 }): Promise<Omit<ScenarioResult, 'skipped'>> => {
 	const startTs = Date.now()
-	const scenarioLogger = logger({ getRelativeTs })
+	const scenarioLogger = logger({
+		getRelativeTs,
+		context: scenario,
+		...logObserver,
+	})
 	const stepResults: [Step, StepResult][] = []
 
 	let aborted = false
@@ -58,6 +64,7 @@ export const runScenario = async <Context extends Record<string, any>>({
 			getRelativeTs,
 			featureLogger,
 			scenarioLogger,
+			logObserver,
 		})
 		stepResults.push([
 			step,