fix(logger-plugin): log async action completion in a separate console group

packages/logger-plugin/src/action-logger.ts

@@ -5,17 +5,18 @@ 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
@@ -27,19 +28,41 @@ export class ActionLogger {
   }
 
   completed(nextState: any) {
+    if (this._synchronousWorkEnded) {
+      this.logWriter.startGroup(`(async work completed) ${this._getActionLogHeader()}`);
+    }
     this.logWriter.logGreen('next state', nextState);
     this.logWriter.endGroup();
+    this._actionCompleted = true;
   }
 
   errored(error: any) {
+    if (this._synchronousWorkEnded) {
+      this.logWriter.startGroup(`(async work error) ${this._getActionLogHeader()}`);
+    }
     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);
+    return `action ${actionName} (started @ ${formattedTime})`;
   }
 
   private _hasPayload(event: any) {
-    const nonEmptyProperties = this._getNonEmptyProperties(event);
-    return nonEmptyProperties.length > 0;
+    return this._getNonEmptyProperties(event).length > 0;
   }
 
   private _getNonEmptyProperties(event: any) {

packages/logger-plugin/src/logger.plugin.ts

@@ -1,7 +1,7 @@
 import { inject, Injectable, Injector, runInInjectionContext } from '@angular/core';
 import { Store } from '@ngxs/store';
 import { NgxsNextPluginFn, NgxsPlugin } from '@ngxs/store/plugins';
-import { catchError, tap } from 'rxjs';
+import { catchError, defer, EMPTY, merge, Observable, tap } from 'rxjs';
 
 import { LogWriter } from './log-writer';
 import { ActionLogger } from './action-logger';
@@ -28,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);
       }),
@@ -37,6 +37,8 @@ export class NgxsLoggerPlugin implements NgxsPlugin {
         throw error;
       })
     );
+
+    return afterSubscribe(result, () => actionLogger.syncWorkComplete());
   }
 
   private _skipLogging(state: any, event: any) {
@@ -50,3 +52,13 @@ export class NgxsLoggerPlugin implements NgxsPlugin {
     return !allowLogging;
   }
 }
+
+function afterSubscribe<T>(source: Observable<T>, callback: VoidFunction): Observable<T> {
+  return merge(
+    source,
+    defer(() => {
+      callback();
+      return EMPTY;
+    })
+  );
+}

packages/logger-plugin/tests/helpers/symbols.ts

@@ -1 +1 @@
-export type CallStack = (string | {})[][];
+export type CallStack = (string | {} | undefined)[][];

packages/logger-plugin/tests/helpers/utils.ts

@@ -18,7 +18,7 @@ export function formatActionCallStack(options: FormatActionCallStackOptions): Ca
     : [];
 
   const formattedCallstack = [
-    [collapsed ? 'groupCollapsed' : 'group', `action ${action} @ `],
+    [collapsed ? 'groupCollapsed' : 'group', `action ${action} (started @ )`],
     ...formattedPayload,
     ['log', '%c prev state', 'color: #9E9E9E; font-weight: bold', { test: prevState }]
   ];

packages/logger-plugin/tests/logger.plugin.spec.ts

@@ -6,7 +6,8 @@ import {
   State,
   StateContext
 } from '@ngxs/store';
-import { throwError } from 'rxjs';
+import { of, throwError } from 'rxjs';
+import { delay, tap } from 'rxjs/operators';
 
 import { setupWithLogger, formatActionCallStack, LoggerSpy } from './helpers';
 
@@ -24,6 +25,16 @@ describe('NgxsLoggerPlugin', () => {
     static type = 'ERROR';
   }
 
+  class AsyncAction {
+    static type = 'ASYNC_ACTION';
+    constructor(public bar?: string) {}
+  }
+
+  class AsyncError {
+    static type = 'ASYNC_ERROR';
+    constructor(public message: string) {}
+  }
+
   interface StateModel {
     bar: string;
   }
@@ -47,6 +58,27 @@ describe('NgxsLoggerPlugin', () => {
     error() {
       return throwError(new Error(thrownErrorMessage));
     }
+
+    @Action(AsyncAction)
+    asyncAction({ patchState }: StateContext<StateModel>, { bar }: AsyncAction) {
+      patchState({ bar: '...' });
+      return of(null).pipe(
+        delay(1),
+        tap(() => patchState({ bar: bar || defaultBarValue }))
+      );
+    }
+
+    @Action(AsyncError)
+    asyncErrorAction({ patchState }: StateContext<StateModel>, { message }: AsyncError) {
+      patchState({ bar: '...' });
+      return of(null).pipe(
+        delay(1),
+        tap(() => {
+          patchState({ bar: 'erroring' });
+          throw new Error(message);
+        })
+      );
+    }
   }
 
   it('should log success action', () => {
@@ -153,6 +185,99 @@ describe('NgxsLoggerPlugin', () => {
     expect(logger.callStack).toEqual(expectedCallStack);
   });
 
+  it('should log async success action', async () => {
+    const { store, logger } = setupWithLogger([TestState]);
+    const payload = 'qux';
+
+    const promise = store.dispatch(new AsyncAction(payload)).toPromise();
+    logger.log('Some other work');
+    await promise;
+
+    const expectedCallStack = LoggerSpy.createCallStack([
+      ...formatActionCallStack({ action: InitState.type, prevState: stateModelDefaults }),
+      ['group', 'action ASYNC_ACTION (started @ )'],
+      ['log', '%c payload', 'color: #9E9E9E; font-weight: bold', { bar: payload }],
+      [
+        'log',
+        '%c prev state',
+        'color: #9E9E9E; font-weight: bold',
+        { test: stateModelDefaults }
+      ],
+      [
+        '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: payload } }
+      ],
+      ['groupEnd']
+    ]);
+
+    expect(logger.callStack).toEqual(expectedCallStack);
+  });
+
+  it('should log async error action', async () => {
+    const { store, logger } = setupWithLogger([TestState]);
+    const errorMessage = 'qux error';
+
+    const promise = store.dispatch(new AsyncError(errorMessage)).toPromise();
+    logger.log('Some other work');
+    try {
+      await promise;
+    } catch {}
+
+    const expectedCallStack = LoggerSpy.createCallStack([
+      ...formatActionCallStack({ action: InitState.type, prevState: stateModelDefaults }),
+      ['group', 'action ASYNC_ERROR (started @ )'],
+      ['log', '%c payload', 'color: #9E9E9E; font-weight: bold', { message: errorMessage }],
+      [
+        'log',
+        '%c prev state',
+        'color: #9E9E9E; font-weight: bold',
+        { test: stateModelDefaults }
+      ],
+      [
+        '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(errorMessage)],
+      ['groupEnd']
+    ]);
+
+    expect(logger.callStack).toEqual(expectedCallStack);
+  });
+
   it('should pass state snapshot to filter predicate', () => {
     const { store, logger } = setupWithLogger([TestState], {
       filter: (_, state) => state.test.bar