diff --git a/STEP_LOGGING_FIX.md b/STEP_LOGGING_FIX.md new file mode 100644 index 000000000..23b9755b0 --- /dev/null +++ b/STEP_LOGGING_FIX.md @@ -0,0 +1,45 @@ +# Step Logging Fix Documentation + +## Problem Statement +Steps were not printed in logs when running either `--verbose` or `--debug` when the I actor method is called not directly in Scenario test file (e.g., in custom steps or page objects) and the custom step doesn't call any child I steps. + +## Root Cause +The `MetaStep.run()` method in `lib/step/meta.js` never emitted `event.step.started` and `event.step.finished` events for itself. It only registered a listener to attach itself to child steps. If no child steps were called, the MetaStep was never printed in verbose/debug output. + +## Solution +Modified `lib/step/meta.js` to track whether child steps are registered and conditionally emit events only if no children are registered. This prevents duplicate printing while ensuring standalone MetaSteps are visible in output. + +## Files Changed +1. `lib/step/meta.js` - Core logic fix +2. `test/unit/step/meta_step_logging_test.js` - Comprehensive unit tests + +## Testing +- ✅ 6 new unit tests (all passing) +- ✅ Manual testing with custom steps (verified fix works) +- ✅ Existing tests (no regression) +- ✅ Security scan (CodeQL: 0 alerts) +- ✅ Linting (ESLint: 0 errors) + +## Example Output + +### Before Fix +``` + test with custom step WITHOUT I calls + Scenario() +This is just a console.log + ✔ OK in 5ms +``` +❌ Step name "I customStepWithoutI" is NOT printed + +### After Fix +``` + test with custom step WITHOUT I calls + Scenario() +This is just a console.log + I custom step without i + ✔ OK in 6ms +``` +✅ Step name is now visible! + +## Known Limitation +For synchronous MetaSteps without child steps, the step name appears after the function executes (because events are emitted in the finally block). This is an acceptable trade-off to avoid the complexity of predicting whether child steps will be registered. diff --git a/lib/step/meta.js b/lib/step/meta.js index 22da5c9f3..6caa9b2d8 100644 --- a/lib/step/meta.js +++ b/lib/step/meta.js @@ -58,17 +58,24 @@ class MetaStep extends Step { this.status = 'queued' this.setArguments(Array.from(arguments).slice(1)) let result + let hasChildSteps = false const registerStep = step => { this.setMetaStep(null) step.setMetaStep(this) + hasChildSteps = true } event.dispatcher.prependListener(event.step.before, registerStep) + + // Start timing + this.startTime = Date.now() + // Handle async and sync methods. if (fn.constructor.name === 'AsyncFunction') { result = fn .apply(this.context, this.args) .then(result => { + this.setStatus('success') return result }) .catch(error => { @@ -78,17 +85,27 @@ class MetaStep extends Step { .finally(() => { this.endTime = Date.now() event.dispatcher.removeListener(event.step.before, registerStep) + // Only emit events if no child steps were registered + if (!hasChildSteps) { + event.emit(event.step.started, this) + event.emit(event.step.finished, this) + } }) } else { try { - this.startTime = Date.now() result = fn.apply(this.context, this.args) + this.setStatus('success') } catch (error) { this.setStatus('failed') throw error } finally { this.endTime = Date.now() event.dispatcher.removeListener(event.step.before, registerStep) + // Only emit events if no child steps were registered + if (!hasChildSteps) { + event.emit(event.step.started, this) + event.emit(event.step.finished, this) + } } } diff --git a/test/unit/step/meta_step_logging_test.js b/test/unit/step/meta_step_logging_test.js new file mode 100644 index 000000000..3259df175 --- /dev/null +++ b/test/unit/step/meta_step_logging_test.js @@ -0,0 +1,115 @@ +import { expect } from 'chai' +import sinon from 'sinon' +import event from '../../../lib/event.js' +import MetaStep from '../../../lib/step/meta.js' +import Step from '../../../lib/step.js' + +describe('MetaStep Logging', () => { + let eventStub + + beforeEach(() => { + event.cleanDispatcher() + eventStub = { + stepStarted: sinon.spy(), + stepFinished: sinon.spy(), + } + event.dispatcher.on(event.step.started, eventStub.stepStarted) + event.dispatcher.on(event.step.finished, eventStub.stepFinished) + }) + + afterEach(() => { + event.cleanDispatcher() + }) + + it('should emit step.started and step.finished for MetaStep without child steps', () => { + const metaStep = new MetaStep('I', 'doSomething') + const fn = () => { + // MetaStep that doesn't call any child I steps + console.log('Just a console.log') + } + + metaStep.run(fn) + + // Should emit step.started and step.finished + expect(eventStub.stepStarted.calledOnce).to.be.true + expect(eventStub.stepFinished.calledOnce).to.be.true + expect(eventStub.stepStarted.firstCall.args[0]).to.equal(metaStep) + expect(eventStub.stepFinished.firstCall.args[0]).to.equal(metaStep) + }) + + it('should NOT emit events for MetaStep WITH child steps', () => { + const metaStep = new MetaStep('I', 'doSomethingWithChild') + const fn = () => { + // Simulate a child step being registered + const childStep = new Step({ helper: 'test' }, 'childAction') + event.emit(event.step.before, childStep) + } + + metaStep.run(fn) + + // Should NOT emit step.started and step.finished for the MetaStep + // because it has child steps + expect(eventStub.stepStarted.called).to.be.false + expect(eventStub.stepFinished.called).to.be.false + }) + + it('should emit events for async MetaStep without child steps', async () => { + const metaStep = new MetaStep('I', 'doSomethingAsync') + const fn = async () => { + // Async MetaStep that doesn't call any child I steps + await Promise.resolve() + console.log('Just an async operation') + } + + await metaStep.run(fn) + + // Should emit step.started and step.finished + expect(eventStub.stepStarted.calledOnce).to.be.true + expect(eventStub.stepFinished.calledOnce).to.be.true + expect(eventStub.stepStarted.firstCall.args[0]).to.equal(metaStep) + expect(eventStub.stepFinished.firstCall.args[0]).to.equal(metaStep) + }) + + it('should NOT emit events for async MetaStep WITH child steps', async () => { + const metaStep = new MetaStep('I', 'doSomethingAsyncWithChild') + const fn = async () => { + // Simulate a child step being registered + const childStep = new Step({ helper: 'test' }, 'childAction') + event.emit(event.step.before, childStep) + await Promise.resolve() + } + + await metaStep.run(fn) + + // Should NOT emit step.started and step.finished for the MetaStep + // because it has child steps + expect(eventStub.stepStarted.called).to.be.false + expect(eventStub.stepFinished.called).to.be.false + }) + + it('should set status to success when MetaStep completes without error', () => { + const metaStep = new MetaStep('I', 'doSomething') + const fn = () => { + return 'success' + } + + metaStep.run(fn) + + expect(metaStep.status).to.equal('success') + }) + + it('should set status to failed when MetaStep throws error', () => { + const metaStep = new MetaStep('I', 'doSomethingThatFails') + const fn = () => { + throw new Error('Test error') + } + + try { + metaStep.run(fn) + } catch (err) { + // Expected to throw + } + + expect(metaStep.status).to.equal('failed') + }) +})