WIP - fix(logger-plugin): log async completion in separate group

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) {

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);
     }

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<T>(source: Observable<T>, callback: VoidFunction) {
+  return merge(
+    source,
+    defer(() => {
+      callback();
+      return empty();
+    })
+  );
+}

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;
 }

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[];