Delay summary timings output until finished (#431)

This fixes the problem that summary timings are printed before grouped output (Fixes #316).

Author: kayahr

src/flow-control/log-timings.spec.ts

@@ -57,13 +57,15 @@ it('returns same commands', () => {
 
 it("does not log timings and doesn't throw if no logger is provided", () => {
     controller = new LogTimings({});
-    controller.handle(commands);
+    const { onFinish } = controller.handle(commands);
 
     commands[0].timer.next({ startDate: startDate0 });
     commands[1].timer.next({ startDate: startDate1 });
     commands[1].timer.next({ startDate: startDate1, endDate: endDate1 });
     commands[0].timer.next({ startDate: startDate0, endDate: endDate0 });
 
+    onFinish?.();
+
     expect(logger.logCommandEvent).toHaveBeenCalledTimes(0);
 });
 
@@ -101,20 +103,26 @@ it('logs the timings at the start and end (ie complete or error) event of each c
 });
 
 it('does not log timings summary if there was an error', () => {
-    controller.handle(commands);
+    const { onFinish } = controller.handle(commands);
 
     commands[0].close.next(command0ExitInfo);
     commands[1].error.next(undefined);
 
+    onFinish?.();
+
     expect(logger.logTable).toHaveBeenCalledTimes(0);
 });
 
-it('logs the sorted timings summary when all processes close successfully', () => {
-    controller.handle(commands);
+it('logs the sorted timings summary when all processes close successfully after onFinish is called', () => {
+    const { onFinish } = controller.handle(commands);
 
     commands[0].close.next(command0ExitInfo);
     commands[1].close.next(command1ExitInfo);
 
+    expect(logger.logGlobalEvent).toHaveBeenCalledTimes(0);
+
+    onFinish?.();
+
     expect(logger.logGlobalEvent).toHaveBeenCalledTimes(1);
     expect(logger.logGlobalEvent).toHaveBeenCalledWith('Timings:');
     expect(logger.logTable).toHaveBeenCalledTimes(1);

src/flow-control/log-timings.ts

@@ -2,7 +2,7 @@ import * as assert from 'assert';
 import formatDate from 'date-fns/format';
 import _ from 'lodash';
 import * as Rx from 'rxjs';
-import { bufferCount, take } from 'rxjs/operators';
+import { bufferCount, combineLatestWith, take } from 'rxjs/operators';
 
 import { CloseEvent, Command } from '../command';
 import * as defaults from '../defaults';
@@ -97,11 +97,13 @@ export class LogTimings implements FlowController {
 
         // overall summary timings
         const closeStreams = commands.map((command) => command.close);
+        const finished = new Rx.Subject<void>();
         const allProcessesClosed = Rx.merge(...closeStreams).pipe(
             bufferCount(closeStreams.length),
-            take(1)
+            take(1),
+            combineLatestWith(finished)
         );
-        allProcessesClosed.subscribe((exitInfos) => this.printExitInfoTimingTable(exitInfos));
-        return { commands };
+        allProcessesClosed.subscribe(([exitInfos]) => this.printExitInfoTimingTable(exitInfos));
+        return { commands, onFinish: () => finished.next() };
     }
 }