Fix procRunner/x-pack ftr scripts (#18789) (#18888)

* [x-pack/ftr] call fatalErrorHandler when functional tests fail

* [kbn/dev-tools/withProcRunner] require a log as the first arg

* [kbn/dev-tools/procRunner] use correct promise, convert to getter

* [x-pack/ftr] avoid race condition that prevents success message logging

When starting the kibana server it is possible for log messages to come
after the server is started, so we added a pause that waits for 5
seconds of logging silence before logging the success message. The
observable used fails to complete though if a log message is never
written AFTER the Kibana server starts. To counter this the observable
is started with `null` so it will always start at least one 5 second
timer and always complete even if there is no log data after Kibana
server starts.

* fix typo

packages/kbn-dev-utils/src/proc_runner/__tests__/with_proc_runner.js

@@ -1,3 +1,4 @@
+import { createToolingLog } from '../../tooling_log';
 import { withProcRunner } from '../with_proc_runner';
 
 describe('proc runner', () => {
@@ -14,7 +15,7 @@ describe('proc runner', () => {
   }
 
   it('passes procs to a function', async () => {
-    await withProcRunner(async procs => {
+    await withProcRunner(createToolingLog(), async procs => {
       await runProc({ procs });
       await procs.stop('proc');
     });

packages/kbn-dev-utils/src/proc_runner/log.js

@@ -1,4 +0,0 @@
-import { createToolingLog } from '../tooling_log';
-
-export const log = createToolingLog('debug');
-log.pipe(process.stdout);

packages/kbn-dev-utils/src/proc_runner/proc.js

@@ -8,7 +8,6 @@ import treeKill from 'tree-kill';
 import { promisify } from 'util';
 const treeKillAsync = promisify(treeKill);
 
-import { log } from './log';
 import { observeLines } from './observe_lines';
 import { createCliError } from './errors';
 
@@ -34,7 +33,7 @@ async function withTimeout(attempt, ms, onTimeout) {
   }
 }
 
-export function createProc(name, { cmd, args, cwd, env, stdin }) {
+export function createProc(name, { cmd, args, cwd, env, stdin, log }) {
   log.info('[%s] > %s', name, cmd, args.join(' '));
 
   // spawn fails with ENOENT when either the
@@ -93,11 +92,15 @@ export function createProc(name, { cmd, args, cwd, env, stdin }) {
       return Rx.Observable.race(exit$, error$);
     }).share()
 
-    outcomePromise = Rx.Observable.merge(
+    _outcomePromise = Rx.Observable.merge(
       this.lines$.ignoreElements(),
       this.outcome$
     ).toPromise();
 
+    getOutcomePromise() {
+      return this._outcomePromise;
+    }
+
     async stop(signal) {
       await withTimeout(
         async () => {
@@ -113,7 +116,7 @@ export function createProc(name, { cmd, args, cwd, env, stdin }) {
       await withTimeout(
         async () => {
           try {
-            await this.outcomePromise;
+            await this.getOutcomePromise();
           } catch (error) {
             // ignore
           }

packages/kbn-dev-utils/src/proc_runner/proc_runner.js

@@ -1,6 +1,5 @@
 import moment from 'moment';
 
-import { log } from './log';
 import { createCliError } from './errors';
 import { createProc } from './proc';
 import { observeSignals } from './observe_signals';
@@ -15,9 +14,12 @@ const noop = () => {};
  *  @class ProcRunner
  */
 export class ProcRunner {
-  constructor() {
+  constructor(options) {
+    const { log } = options;
+
     this._closing = false;
     this._procs = [];
+    this._log = log;
     this._signalSubscription = observeSignals(process).subscribe({
       next: async (signal) => {
         await this.teardown(signal);
@@ -84,7 +86,7 @@ export class ProcRunner {
 
       // wait for process to complete
       if (wait === true) {
-        await proc.outcomePromise;
+        await proc.getOutcomePromise();
       }
     } finally {
       // while the procRunner closes promises will resolve/reject because
@@ -107,7 +109,7 @@ export class ProcRunner {
     if (proc) {
       await proc.stop(signal);
     } else {
-      log.warning('[%s] already stopped', name);
+      this._log.warning('[%s] already stopped', name);
     }
   }
 
@@ -117,7 +119,7 @@ export class ProcRunner {
    */
   async waitForAllToStop() {
     await Promise.all(
-      this._procs.map(proc => proc.closedPromise)
+      this._procs.map(proc => proc.getOutcomePromise())
     );
   }
 
@@ -136,7 +138,7 @@ export class ProcRunner {
     this._signalSubscription = null;
 
     if (!signal && this._procs.length > 0) {
-      log.warning(
+      this._log.warning(
         '%d processes left running, stop them with procs.stop(name):',
         this._procs.length,
         this._procs.map(proc => proc.name)
@@ -155,7 +157,10 @@ export class ProcRunner {
 
   _createProc(name, options) {
     const startMs = Date.now();
-    const proc = createProc(name, options);
+    const proc = createProc(name, {
+      ...options,
+      log: this._log,
+    });
 
     this._procs.push(proc);
     const remove = () => {
@@ -166,14 +171,14 @@ export class ProcRunner {
     proc.outcome$.subscribe({
       next: (code) => {
         const duration = moment.duration(Date.now() - startMs);
-        log.info('[%s] exitted with %s after %s', name, code, duration.humanize());
+        this._log.info('[%s] exitted with %s after %s', name, code, duration.humanize());
       },
       complete: () => {
         remove();
       },
       error: (error) => {
         if (this._closing) {
-          log.error(error);
+          this._log.error(error);
         }
         remove();
       },

packages/kbn-dev-utils/src/proc_runner/with_proc_runner.js

@@ -5,11 +5,12 @@ import { ProcRunner } from './proc_runner';
  *  the async function finishes the ProcRunner is torn-down
  *  automatically
  *
+ *  @param  {ToolingLog} log
  *  @param  {async Function} fn
  *  @return {Promise<undefined>}
  */
-export async function withProcRunner(fn) {
-  const procs = new ProcRunner();
+export async function withProcRunner(log, fn) {
+  const procs = new ProcRunner({ log });
   try {
     await fn(procs);
   } finally {

x-pack/dev-tools/functional_tests/tasks.js

@@ -35,40 +35,44 @@ export function fatalErrorHandler(err) {
 }
 
 export async function runFunctionTests() {
-  const cmd = new Command('node scripts/functional_tests');
+  try {
+    const cmd = new Command('node scripts/functional_tests');
 
-  cmd
-    .option(
-      '--bail',
-      'Stop the functional_test_runner as soon as a failure occurs'
-    )
-    .option(
-      '--kibana-install-dir <path>',
-      'Run Kibana from an existing install directory'
-    )
-    .option(
-      '--es-from <from>',
-      'Run ES from either source or snapshot [default: snapshot]'
-    )
-    .parse(process.argv);
+    cmd
+      .option(
+        '--bail',
+        'Stop the functional_test_runner as soon as a failure occurs'
+      )
+      .option(
+        '--kibana-install-dir <path>',
+        'Run Kibana from an existing install directory'
+      )
+      .option(
+        '--es-from <from>',
+        'Run ES from either source or snapshot [default: snapshot]'
+      )
+      .parse(process.argv);
 
-  await withProcRunner(async procs => {
-    const ftrConfig = await getFtrConfig();
+    await withProcRunner(log, async procs => {
+      const ftrConfig = await getFtrConfig();
 
-    const es = await runEsWithXpack({ ftrConfig, from: cmd.esFrom });
-    await runKibanaServer({
-      procs,
-      ftrConfig,
-      existingInstallDir: cmd.kibanaInstallDir,
+      const es = await runEsWithXpack({ ftrConfig, from: cmd.esFrom });
+      await runKibanaServer({
+        procs,
+        ftrConfig,
+        existingInstallDir: cmd.kibanaInstallDir,
+      });
+      await runFtr({
+        procs,
+        bail: cmd.bail,
+      });
+
+      await procs.stop('kibana');
+      await es.cleanup();
     });
-    await runFtr({
-      procs,
-      bail: cmd.bail,
-    });
-
-    await procs.stop('kibana');
-    await es.cleanup();
-  });
+  } catch (err) {
+    fatalErrorHandler(err);
+  }
 }
 
 export async function runApiTests() {
@@ -90,7 +94,7 @@ export async function runApiTests() {
     .parse(process.argv);
 
   try {
-    await withProcRunner(async procs => {
+    await withProcRunner(log, async procs => {
       const ftrConfig = await getFtrConfig();
 
       const es = await runEsWithXpack({ ftrConfig, from: cmd.esFrom });
@@ -155,7 +159,7 @@ export async function runFunctionalTestsServer() {
   const useSAML = cmd.saml;
 
   try {
-    await withProcRunner(async procs => {
+    await withProcRunner(log, async procs => {
       const ftrConfig = await getFtrConfig();
       await runEsWithXpack({ ftrConfig, useSAML, from: cmd.esFrom });
       await runKibanaServer({
@@ -165,14 +169,15 @@ export async function runFunctionalTestsServer() {
         useSAML,
       });
 
-      // wait for 5 seconds of silence before logging the success message
-      // so that it doesn't get burried
+      // wait for 5 seconds of silence before logging the
+      // success message so that it doesn't get buried
       await Rx.Observable.fromEvent(log, 'data')
+        .startWith(null)
         .switchMap(() => Rx.Observable.timer(5000))
-        .first()
+        .take(1)
         .toPromise();
 
-      log.info(SUCCESS_MESSAGE);
+      log.success(SUCCESS_MESSAGE);
       await procs.waitForAllToStop();
     });
   } catch (err) {