From b7e8ebdc21754e9b7ebf3bec13a91915499f792a Mon Sep 17 00:00:00 2001 From: markwhitfeld Date: Sat, 24 Aug 2019 13:27:32 +0200 Subject: [PATCH 1/5] chore(logger-plugin): improve helpers for better testing --- .../logger-plugin/tests/helpers/logger-spy.ts | 32 ++++++++++++++----- .../logger-plugin/tests/helpers/symbols.ts | 4 ++- 2 files changed, 27 insertions(+), 9 deletions(-) diff --git a/packages/logger-plugin/tests/helpers/logger-spy.ts b/packages/logger-plugin/tests/helpers/logger-spy.ts index 192e6a7ac..01c47f5ec 100644 --- a/packages/logger-plugin/tests/helpers/logger-spy.ts +++ b/packages/logger-plugin/tests/helpers/logger-spy.ts @@ -1,4 +1,4 @@ -import { CallStack } from './symbols'; +import { CallStack, Call } from './symbols'; /** * Spy that mimics the required methods for custom logger implementation, @@ -28,17 +28,33 @@ export class LoggerSpy { } get callStack(): string { - const callStackWithoutTime = this._callStack.map(call => { - const callSecondParam = call[1] as string; + const callStackWithoutTime = this.getCallStack(); + return LoggerSpy.createCallStack(callStackWithoutTime); + } - // remove formatted time string - if (typeof callSecondParam === 'string') { - call[1] = callSecondParam.replace(/\d{2}:\d{2}:\d{2}.\d{3}/g, ''); + getCallStack(options: { excludeStyles?: boolean } = {}): any[] { + return this._callStack.map(call => { + call = removeTime(call); + if (options.excludeStyles) { + call = removeStyle(call); } - return call; }); + } +} - return LoggerSpy.createCallStack(callStackWithoutTime); +function removeTime(item: Call): Call { + const [first, second, ...rest] = item; + if (typeof second === 'string') { + return [first, second.replace(/\d{2}:\d{2}:\d{2}.\d{3}/g, ''), ...rest]; + } + return item; +} + +function removeStyle(item: Call): Call { + const [first, second /*third*/, , ...rest] = item; + if (typeof second === 'string' && second.startsWith('%c ')) { + return [first, second.substring(3), '', ...rest]; } + return item; } diff --git a/packages/logger-plugin/tests/helpers/symbols.ts b/packages/logger-plugin/tests/helpers/symbols.ts index d730e8f17..c921fa6dd 100644 --- a/packages/logger-plugin/tests/helpers/symbols.ts +++ b/packages/logger-plugin/tests/helpers/symbols.ts @@ -1 +1,3 @@ -export type CallStack = (string | {})[][]; +export type CallParam = string | {}; +export type Call = CallParam[]; +export type CallStack = Call[]; From 26b546049441f39a8481e80da9e76ce6ba3e1c17 Mon Sep 17 00:00:00 2001 From: markwhitfeld Date: Sat, 24 Aug 2019 14:37:34 +0200 Subject: [PATCH 2/5] chore(logger-plugin): clean up tests to make them more explicit --- .../logger-plugin/tests/helpers/logger-spy.ts | 8 +- .../logger-plugin/tests/logger.plugin.spec.ts | 132 ++++++++++-------- 2 files changed, 81 insertions(+), 59 deletions(-) diff --git a/packages/logger-plugin/tests/helpers/logger-spy.ts b/packages/logger-plugin/tests/helpers/logger-spy.ts index 01c47f5ec..07c0ea9b0 100644 --- a/packages/logger-plugin/tests/helpers/logger-spy.ts +++ b/packages/logger-plugin/tests/helpers/logger-spy.ts @@ -27,6 +27,10 @@ export class LoggerSpy { this._callStack.push(['log', message, ...optionalParams]); } + clear() { + this._callStack = []; + } + get callStack(): string { const callStackWithoutTime = this.getCallStack(); return LoggerSpy.createCallStack(callStackWithoutTime); @@ -52,9 +56,9 @@ function removeTime(item: Call): Call { } function removeStyle(item: Call): Call { - const [first, second /*third*/, , ...rest] = item; + const [first, second, , ...rest] = item; if (typeof second === 'string' && second.startsWith('%c ')) { - return [first, second.substring(3), '', ...rest]; + return [first, second.substring(3), ...rest]; } return item; } diff --git a/packages/logger-plugin/tests/logger.plugin.spec.ts b/packages/logger-plugin/tests/logger.plugin.spec.ts index ef089eb87..457d38a05 100644 --- a/packages/logger-plugin/tests/logger.plugin.spec.ts +++ b/packages/logger-plugin/tests/logger.plugin.spec.ts @@ -2,12 +2,12 @@ import { ErrorHandler } from '@angular/core'; import { TestBed } from '@angular/core/testing'; import { throwError } from 'rxjs'; -import { NgxsModule, Store, State, Action, StateContext, InitState } from '@ngxs/store'; +import { NgxsModule, Store, State, Action, StateContext } from '@ngxs/store'; import { NoopErrorHandler } from '@ngxs/store/tests/helpers/utils'; import { StateClass } from '@ngxs/store/internals'; import { NgxsLoggerPluginModule, NgxsLoggerPluginOptions } from '../'; -import { LoggerSpy, formatActionCallStack } from './helpers'; +import { LoggerSpy } from './helpers'; describe('NgxsLoggerPlugin', () => { const thrownErrorMessage = 'Error'; @@ -69,93 +69,111 @@ describe('NgxsLoggerPlugin', () => { }; } - it('should log success action', () => { + it('should log init action success with colors', () => { + // Arrange & Act const { store, logger } = setup([TestState]); + const initialState = store.selectSnapshot(state => state); + // Assert + const expectedCallStack = [ + ['group', 'action @@INIT @ '], + ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', initialState], + ['log', '%c next state', 'color: #4CAF50; font-weight: bold', initialState], + ['groupEnd'] + ]; + expect(logger.getCallStack()).toEqual(expectedCallStack); + }); - store.dispatch(new UpdateBarAction()); - - const expectedCallStack = LoggerSpy.createCallStack([ - ...formatActionCallStack({ action: InitState.type, prevState: stateModelDefaults }), + it('should log success action with colors', () => { + // Arrange + const { store, logger } = setup([TestState]); + logger.clear(); + const initialState = store.selectSnapshot(state => state); - ...formatActionCallStack({ - action: UpdateBarAction.type, - prevState: stateModelDefaults, - nextState: { bar: defaultBarValue } - }) - ]); + // Act + store.dispatch(new UpdateBarAction()); - expect(logger.callStack).toEqual(expectedCallStack); + // Assert + const newState = store.selectSnapshot(state => state); + const expectedCallStack = [ + ['group', 'action UPDATE_BAR @ '], + ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', initialState], + ['log', '%c next state', 'color: #4CAF50; font-weight: bold', newState], + ['groupEnd'] + ]; + expect(logger.getCallStack()).toEqual(expectedCallStack); }); it('should log success action with payload', () => { + // Arrange const { store, logger } = setup([TestState]); + logger.clear(); const payload = 'qux'; + // Act store.dispatch(new UpdateBarAction(payload)); - const expectedCallStack = LoggerSpy.createCallStack([ - ...formatActionCallStack({ action: InitState.type, prevState: stateModelDefaults }), - - ...formatActionCallStack({ - action: UpdateBarAction.type, - prevState: stateModelDefaults, - nextState: { bar: payload }, - payload: { bar: payload } - }) - ]); - - expect(logger.callStack).toEqual(expectedCallStack); + // Assert + const expectedCallStack = [ + ['group', 'action UPDATE_BAR @ '], + ['log', '%c payload', 'color: #9E9E9E; font-weight: bold', { bar: 'qux' }], + ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', { test: { bar: '' } }], + ['log', '%c next state', 'color: #4CAF50; font-weight: bold', { test: { bar: 'qux' } }], + ['groupEnd'] + ]; + expect(logger.getCallStack()).toEqual(expectedCallStack); }); - it('should log error action', () => { + it('should log error action with colors', () => { + // Arrange const { store, logger } = setup([TestState]); + logger.clear(); + // Act store.dispatch(new ErrorAction()); - const expectedCallStack = LoggerSpy.createCallStack([ - ...formatActionCallStack({ action: InitState.type, prevState: stateModelDefaults }), - - ...formatActionCallStack({ - action: ErrorAction.type, - prevState: stateModelDefaults, - error: thrownErrorMessage, - snapshot: store.snapshot() - }) - ]); + // Assert + const expectedCallStack = [ + ['group', 'action ERROR @ '], + ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', { test: { bar: '' } }], + [ + 'log', + '%c next state after error', + 'color: #FD8182; font-weight: bold', + { test: { bar: '' } } + ], + ['log', '%c error', 'color: #FD8182; font-weight: bold', new Error('Error')], + ['groupEnd'] + ]; - expect(logger.callStack).toEqual(expectedCallStack); + expect(logger.getCallStack()).toEqual(expectedCallStack); }); it('should log collapsed success action', () => { + // Arrange const { store, logger } = setup([TestState], { collapsed: true }); + logger.clear(); + // Act store.dispatch(new UpdateBarAction()); - const expectedCallStack = LoggerSpy.createCallStack([ - ...formatActionCallStack({ - action: InitState.type, - prevState: stateModelDefaults, - collapsed: true - }), - - ...formatActionCallStack({ - action: UpdateBarAction.type, - prevState: stateModelDefaults, - nextState: { bar: defaultBarValue }, - collapsed: true - }) - ]); - - expect(logger.callStack).toEqual(expectedCallStack); + // Assert + const expectedCallStack = [ + ['groupCollapsed', 'action UPDATE_BAR @ '], + ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', { test: { bar: '' } }], + ['log', '%c next state', 'color: #4CAF50; font-weight: bold', { test: { bar: 'baz' } }], + ['groupEnd'] + ]; + expect(logger.getCallStack()).toEqual(expectedCallStack); }); it('should not log while disabled', () => { + // Arrange const { store, logger } = setup([TestState], { disabled: true }); + // Act store.dispatch(new UpdateBarAction()); - const expectedCallStack = LoggerSpy.createCallStack([]); - - expect(logger.callStack).toEqual(expectedCallStack); + // Assert + expect(logger.getCallStack()).toEqual([]); }); }); From 68862ae83e367ae17f99f3209ab740b9c1e72ecc Mon Sep 17 00:00:00 2001 From: markwhitfeld Date: Sun, 25 Aug 2019 00:53:18 +0200 Subject: [PATCH 3/5] refactor: simplify method --- packages/logger-plugin/src/log-writer.ts | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/packages/logger-plugin/src/log-writer.ts b/packages/logger-plugin/src/log-writer.ts index a721d4dd3..72c58f9ff 100644 --- a/packages/logger-plugin/src/log-writer.ts +++ b/packages/logger-plugin/src/log-writer.ts @@ -8,11 +8,12 @@ export class LogWriter { } startGroup(message: string) { - const startGroupFn = this.options.collapsed - ? this.logger.groupCollapsed - : this.logger.group; try { - startGroupFn.call(this.logger, message); + if (this.options.collapsed) { + this.logger.groupCollapsed(message); + } else { + this.logger.group(message); + } } catch (e) { console.log(message); } From 9a3aff618f97efcf31134281c65e3802efa75de1 Mon Sep 17 00:00:00 2001 From: markwhitfeld Date: Sun, 25 Aug 2019 00:57:20 +0200 Subject: [PATCH 4/5] fix(logger-plugin): log async completion in separate group --- packages/logger-plugin/src/action-logger.ts | 35 ++++- packages/logger-plugin/src/logger.plugin.ts | 15 +- .../logger-plugin/tests/logger.plugin.spec.ts | 129 +++++++++++++++++- 3 files changed, 168 insertions(+), 11 deletions(-) diff --git a/packages/logger-plugin/src/action-logger.ts b/packages/logger-plugin/src/action-logger.ts index 7359c9718..d641db38e 100644 --- a/packages/logger-plugin/src/action-logger.ts +++ b/packages/logger-plugin/src/action-logger.ts @@ -4,13 +4,14 @@ import { formatTime } from './internals'; import { LogWriter } from './log-writer'; export class ActionLogger { + private synchronousWorkEnded = false; + private actionCompleted = false; + private startedTime = new Date(); + constructor(private action: any, private store: Store, private logWriter: LogWriter) {} dispatched(state: any) { - const actionName = getActionTypeFromInstance(this.action); - const formattedTime = formatTime(new Date()); - - const message = `action ${actionName} @ ${formattedTime}`; + const message = this.getActionLogHeader(); this.logWriter.startGroup(message); // print payload only if at least one property is supplied @@ -22,14 +23,40 @@ export class ActionLogger { } completed(nextState: any) { + if (this.synchronousWorkEnded) { + const message = `(async work completed) ${this.getActionLogHeader()}`; + this.logWriter.startGroup(message); + } this.logWriter.logGreen('next state', nextState); this.logWriter.endGroup(); + this.actionCompleted = true; } errored(error: any) { + if (this.synchronousWorkEnded) { + const message = `(async work error) ${this.getActionLogHeader()}`; + this.logWriter.startGroup(message); + } this.logWriter.logRedish('next state after error', this.store.snapshot()); this.logWriter.logRedish('error', error); this.logWriter.endGroup(); + this.actionCompleted = true; + } + + syncWorkComplete() { + if (!this.actionCompleted) { + this.logWriter.logGreen('next state (synchronous)', this.store.snapshot()); + this.logWriter.logGreen('( action doing async work... )', undefined); + this.logWriter.endGroup(); + } + this.synchronousWorkEnded = true; + } + + private getActionLogHeader() { + const actionName = getActionTypeFromInstance(this.action); + const formattedTime = formatTime(this.startedTime); + const message = `action ${actionName} (started @ ${formattedTime})`; + return message; } private _hasPayload(event: any) { diff --git a/packages/logger-plugin/src/logger.plugin.ts b/packages/logger-plugin/src/logger.plugin.ts index e09d11ef8..4da8bdf2e 100644 --- a/packages/logger-plugin/src/logger.plugin.ts +++ b/packages/logger-plugin/src/logger.plugin.ts @@ -1,4 +1,5 @@ import { Injectable, Inject, Injector } from '@angular/core'; +import { Observable, defer, empty, merge } from 'rxjs'; import { tap, catchError } from 'rxjs/operators'; import { NgxsPlugin, NgxsNextPluginFn, Store } from '@ngxs/store'; @@ -27,7 +28,7 @@ export class NgxsLoggerPlugin implements NgxsPlugin { actionLogger.dispatched(state); - return next(state, event).pipe( + const result = next(state, event).pipe( tap(nextState => { actionLogger.completed(nextState); }), @@ -36,5 +37,17 @@ export class NgxsLoggerPlugin implements NgxsPlugin { throw error; }) ); + + return afterSubscribe(result, () => actionLogger.syncWorkComplete()); } } + +function afterSubscribe(source: Observable, callback: VoidFunction) { + return merge( + source, + defer(() => { + callback(); + return empty(); + }) + ); +} diff --git a/packages/logger-plugin/tests/logger.plugin.spec.ts b/packages/logger-plugin/tests/logger.plugin.spec.ts index 457d38a05..f45d7409c 100644 --- a/packages/logger-plugin/tests/logger.plugin.spec.ts +++ b/packages/logger-plugin/tests/logger.plugin.spec.ts @@ -1,6 +1,6 @@ import { ErrorHandler } from '@angular/core'; import { TestBed } from '@angular/core/testing'; -import { throwError } from 'rxjs'; +import { throwError, of } from 'rxjs'; import { NgxsModule, Store, State, Action, StateContext } from '@ngxs/store'; import { NoopErrorHandler } from '@ngxs/store/tests/helpers/utils'; @@ -8,6 +8,7 @@ import { StateClass } from '@ngxs/store/internals'; import { NgxsLoggerPluginModule, NgxsLoggerPluginOptions } from '../'; import { LoggerSpy } from './helpers'; +import { tap, delay } from 'rxjs/operators'; describe('NgxsLoggerPlugin', () => { const thrownErrorMessage = 'Error'; @@ -19,10 +20,21 @@ describe('NgxsLoggerPlugin', () => { constructor(public bar?: string) {} } + class AsyncAction { + static type = 'ASYNC_ACTION'; + + constructor(public bar?: string) {} + } + class ErrorAction { static type = 'ERROR'; } + class AsyncError { + static type = 'ASYNC_ERROR'; + constructor(public message: string) {} + } + interface StateModel { bar: string; } @@ -45,6 +57,29 @@ describe('NgxsLoggerPlugin', () => { error() { return throwError(new Error(thrownErrorMessage)); } + + @Action(AsyncAction) + asyncAction({ patchState }: StateContext, { bar }: AsyncAction) { + patchState({ bar: '...' }); + return of(null).pipe( + delay(1), + tap(() => { + patchState({ bar }); + }) + ); + } + + @Action(AsyncError) + asyncErrorAction({ patchState }: StateContext, { message }: AsyncError) { + patchState({ bar: '...' }); + return of(null).pipe( + delay(1), + tap(() => { + patchState({ bar: 'erroring' }); + throw new Error(message); + }) + ); + } } function setup(states: StateClass[], opts?: NgxsLoggerPluginOptions) { @@ -75,7 +110,7 @@ describe('NgxsLoggerPlugin', () => { const initialState = store.selectSnapshot(state => state); // Assert const expectedCallStack = [ - ['group', 'action @@INIT @ '], + ['group', 'action @@INIT (started @ )'], ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', initialState], ['log', '%c next state', 'color: #4CAF50; font-weight: bold', initialState], ['groupEnd'] @@ -95,7 +130,7 @@ describe('NgxsLoggerPlugin', () => { // Assert const newState = store.selectSnapshot(state => state); const expectedCallStack = [ - ['group', 'action UPDATE_BAR @ '], + ['group', 'action UPDATE_BAR (started @ )'], ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', initialState], ['log', '%c next state', 'color: #4CAF50; font-weight: bold', newState], ['groupEnd'] @@ -114,9 +149,46 @@ describe('NgxsLoggerPlugin', () => { // Assert const expectedCallStack = [ - ['group', 'action UPDATE_BAR @ '], + ['group', 'action UPDATE_BAR (started @ )'], + ['log', '%c payload', 'color: #9E9E9E; font-weight: bold', { bar: 'qux' }], + ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', { test: { bar: '' } }], + ['log', '%c next state', 'color: #4CAF50; font-weight: bold', { test: { bar: 'qux' } }], + ['groupEnd'] + ]; + expect(logger.getCallStack()).toEqual(expectedCallStack); + }); + + it('should log async success action', async () => { + // Arrange + const { store, logger } = setup([TestState]); + logger.clear(); + const payload = 'qux'; + + // Act + const promise = store.dispatch(new AsyncAction(payload)).toPromise(); + logger.log('Some other work'); + await promise; + + // Assert + const expectedCallStack = [ + ['group', 'action ASYNC_ACTION (started @ )'], ['log', '%c payload', 'color: #9E9E9E; font-weight: bold', { bar: 'qux' }], ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', { test: { bar: '' } }], + [ + 'log', + '%c next state (synchronous)', + 'color: #4CAF50; font-weight: bold', + { test: { bar: '...' } } + ], + [ + 'log', + '%c ( action doing async work... )', + 'color: #4CAF50; font-weight: bold', + undefined + ], + ['groupEnd'], + ['log', 'Some other work'], + ['group', '(async work completed) action ASYNC_ACTION (started @ )'], ['log', '%c next state', 'color: #4CAF50; font-weight: bold', { test: { bar: 'qux' } }], ['groupEnd'] ]; @@ -133,7 +205,7 @@ describe('NgxsLoggerPlugin', () => { // Assert const expectedCallStack = [ - ['group', 'action ERROR @ '], + ['group', 'action ERROR (started @ )'], ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', { test: { bar: '' } }], [ 'log', @@ -148,6 +220,51 @@ describe('NgxsLoggerPlugin', () => { expect(logger.getCallStack()).toEqual(expectedCallStack); }); + it('should log async error action', async () => { + // Arrange + const { store, logger } = setup([TestState]); + logger.clear(); + const errorMessage = 'qux error'; + + // Act + const promise = store.dispatch(new AsyncError(errorMessage)).toPromise(); + logger.log('Some other work'); + try { + await promise; + } catch {} + + // Assert + const expectedCallStack = [ + ['group', 'action ASYNC_ERROR (started @ )'], + ['log', '%c payload', 'color: #9E9E9E; font-weight: bold', { message: 'qux error' }], + ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', { test: { bar: '' } }], + [ + 'log', + '%c next state (synchronous)', + 'color: #4CAF50; font-weight: bold', + { test: { bar: '...' } } + ], + [ + 'log', + '%c ( action doing async work... )', + 'color: #4CAF50; font-weight: bold', + undefined + ], + ['groupEnd'], + ['log', 'Some other work'], + ['group', '(async work error) action ASYNC_ERROR (started @ )'], + [ + 'log', + '%c next state after error', + 'color: #FD8182; font-weight: bold', + { test: { bar: 'erroring' } } + ], + ['log', '%c error', 'color: #FD8182; font-weight: bold', new Error('qux error')], + ['groupEnd'] + ]; + expect(logger.getCallStack()).toEqual(expectedCallStack); + }); + it('should log collapsed success action', () => { // Arrange const { store, logger } = setup([TestState], { collapsed: true }); @@ -158,7 +275,7 @@ describe('NgxsLoggerPlugin', () => { // Assert const expectedCallStack = [ - ['groupCollapsed', 'action UPDATE_BAR @ '], + ['groupCollapsed', 'action UPDATE_BAR (started @ )'], ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', { test: { bar: '' } }], ['log', '%c next state', 'color: #4CAF50; font-weight: bold', { test: { bar: 'baz' } }], ['groupEnd'] From d3cfa02e4ea1a6c7066c1393d2684b45e966f6dc Mon Sep 17 00:00:00 2001 From: markwhitfeld Date: Sun, 25 Aug 2019 07:52:08 +0200 Subject: [PATCH 5/5] chore: tweaks from review --- packages/logger-plugin/src/logger.plugin.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/logger-plugin/src/logger.plugin.ts b/packages/logger-plugin/src/logger.plugin.ts index 4da8bdf2e..8dc513d00 100644 --- a/packages/logger-plugin/src/logger.plugin.ts +++ b/packages/logger-plugin/src/logger.plugin.ts @@ -1,5 +1,5 @@ import { Injectable, Inject, Injector } from '@angular/core'; -import { Observable, defer, empty, merge } from 'rxjs'; +import { Observable, defer, EMPTY, merge } from 'rxjs'; import { tap, catchError } from 'rxjs/operators'; import { NgxsPlugin, NgxsNextPluginFn, Store } from '@ngxs/store'; @@ -47,7 +47,7 @@ function afterSubscribe(source: Observable, callback: VoidFunction) { source, defer(() => { callback(); - return empty(); + return EMPTY; }) ); }