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/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); } diff --git a/packages/logger-plugin/src/logger.plugin.ts b/packages/logger-plugin/src/logger.plugin.ts index e09d11ef8..8dc513d00 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/helpers/logger-spy.ts b/packages/logger-plugin/tests/helpers/logger-spy.ts index 192e6a7ac..07c0ea9b0 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, @@ -27,18 +27,38 @@ export class LoggerSpy { this._callStack.push(['log', message, ...optionalParams]); } + clear() { + this._callStack = []; + } + 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, , ...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[]; diff --git a/packages/logger-plugin/tests/logger.plugin.spec.ts b/packages/logger-plugin/tests/logger.plugin.spec.ts index ef089eb87..f45d7409c 100644 --- a/packages/logger-plugin/tests/logger.plugin.spec.ts +++ b/packages/logger-plugin/tests/logger.plugin.spec.ts @@ -1,13 +1,14 @@ 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, 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'; +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) { @@ -69,93 +104,193 @@ 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 (started @ )'], + ['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 (started @ )'], + ['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 }), + // Assert + const expectedCallStack = [ + ['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); + }); - ...formatActionCallStack({ - action: UpdateBarAction.type, - prevState: stateModelDefaults, - nextState: { bar: payload }, - payload: { bar: payload } - }) - ]); + it('should log async success action', async () => { + // Arrange + const { store, logger } = setup([TestState]); + logger.clear(); + const payload = 'qux'; - expect(logger.callStack).toEqual(expectedCallStack); + // 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'] + ]; + 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 }), + // Assert + const expectedCallStack = [ + ['group', 'action ERROR (started @ )'], + ['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'] + ]; - ...formatActionCallStack({ - action: ErrorAction.type, - prevState: stateModelDefaults, - error: thrownErrorMessage, - snapshot: store.snapshot() - }) - ]); + expect(logger.getCallStack()).toEqual(expectedCallStack); + }); - expect(logger.callStack).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 }); + 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 (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'] + ]; + 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([]); }); });