Display Kibana overall status in the logs and have FTR wait for green…

… status before running tests (#102108) (#102511)

Co-authored-by: Josh Dover <1813008+joshdover@users.noreply.github.com>

packages/kbn-test/src/functional_test_runner/lib/config/schema.ts

@@ -187,6 +187,19 @@ export const schema = Joi.object()
         sourceArgs: Joi.array(),
         serverArgs: Joi.array(),
         installDir: Joi.string(),
+        /** Options for how FTR should execute and interact with Kibana */
+        runOptions: Joi.object()
+          .keys({
+            /**
+             * Log message to wait for before initiating tests, defaults to waiting for Kibana status to be `available`.
+             * Note that this log message must not be filtered out by the current logging config, for example by the
+             * log level. If needed, you can adjust the logging level via `kbnTestServer.serverArgs`.
+             */
+            wait: Joi.object()
+              .regex()
+              .default(/Kibana is now available/),
+          })
+          .default(),
       })
       .default(),
 

packages/kbn-test/src/functional_tests/lib/run_kibana_server.js

@@ -28,6 +28,7 @@ function extendNodeOptions(installDir) {
 
 export async function runKibanaServer({ procs, config, options }) {
   const { installDir } = options;
+  const runOptions = config.get('kbnTestServer.runOptions');
 
   await procs.run('kibana', {
     cmd: getKibanaCmd(installDir),
@@ -38,7 +39,7 @@ export async function runKibanaServer({ procs, config, options }) {
       ...extendNodeOptions(installDir),
     },
     cwd: installDir || KIBANA_ROOT,
-    wait: /\[Kibana\]\[http\] http server running/,
+    wait: runOptions.wait,
   });
 }
 

packages/kbn-test/src/functional_tests/tasks.js

@@ -97,8 +97,6 @@ export async function runTests(options) {
       try {
         es = await runElasticsearch({ config, options: opts });
         await runKibanaServer({ procs, config, options: opts });
-        // workaround until https://github.com/elastic/kibana/issues/89828 is addressed
-        await delay(5000);
         await runFtr({ configPath, options: opts });
       } finally {
         try {
@@ -164,7 +162,3 @@ async function silence(log, milliseconds) {
     )
     .toPromise();
 }
-
-async function delay(ms) {
-  await new Promise((resolve) => setTimeout(resolve, ms));
-}

src/core/server/server.ts

@@ -261,6 +261,7 @@ export class Server {
 
     await this.plugins.start(this.coreStart);
 
+    this.status.start();
     await this.http.start();
 
     startTransaction?.end();

src/core/server/status/log_overall_status.test.ts

@@ -0,0 +1,103 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * 2.0 and the Server Side Public License, v 1; you may not use this file except
+ * in compliance with, at your election, the Elastic License 2.0 or the Server
+ * Side Public License, v 1.
+ */
+
+import { TestScheduler } from 'rxjs/testing';
+import { ServiceStatus, ServiceStatusLevels } from './types';
+import { getOverallStatusChanges } from './log_overall_status';
+
+const getTestScheduler = () =>
+  new TestScheduler((actual, expected) => {
+    expect(actual).toEqual(expected);
+  });
+
+const createStatus = (parts: Partial<ServiceStatus> = {}): ServiceStatus => ({
+  level: ServiceStatusLevels.available,
+  summary: 'summary',
+  ...parts,
+});
+
+describe('getOverallStatusChanges', () => {
+  it('emits an initial message after first overall$ emission', () => {
+    getTestScheduler().run(({ expectObservable, hot }) => {
+      const overall$ = hot<ServiceStatus>('--a', {
+        a: createStatus(),
+      });
+      const stop$ = hot<void>('');
+      const expected = '--a';
+
+      expectObservable(getOverallStatusChanges(overall$, stop$)).toBe(expected, {
+        a: 'Kibana is now available',
+      });
+    });
+  });
+
+  it('emits a new message every time the status level changes', () => {
+    getTestScheduler().run(({ expectObservable, hot }) => {
+      const overall$ = hot<ServiceStatus>('--a--b', {
+        a: createStatus({
+          level: ServiceStatusLevels.degraded,
+        }),
+        b: createStatus({
+          level: ServiceStatusLevels.available,
+        }),
+      });
+      const stop$ = hot<void>('');
+      const expected = '--a--b';
+
+      expectObservable(getOverallStatusChanges(overall$, stop$)).toBe(expected, {
+        a: 'Kibana is now degraded',
+        b: 'Kibana is now available (was degraded)',
+      });
+    });
+  });
+
+  it('does not emit when the status stays the same', () => {
+    getTestScheduler().run(({ expectObservable, hot }) => {
+      const overall$ = hot<ServiceStatus>('--a--b--c', {
+        a: createStatus({
+          level: ServiceStatusLevels.degraded,
+          summary: 'summary 1',
+        }),
+        b: createStatus({
+          level: ServiceStatusLevels.degraded,
+          summary: 'summary 2',
+        }),
+        c: createStatus({
+          level: ServiceStatusLevels.available,
+          summary: 'summary 2',
+        }),
+      });
+      const stop$ = hot<void>('');
+      const expected = '--a-----b';
+
+      expectObservable(getOverallStatusChanges(overall$, stop$)).toBe(expected, {
+        a: 'Kibana is now degraded',
+        b: 'Kibana is now available (was degraded)',
+      });
+    });
+  });
+
+  it('stops emitting once `stop$` emits', () => {
+    getTestScheduler().run(({ expectObservable, hot }) => {
+      const overall$ = hot<ServiceStatus>('--a--b', {
+        a: createStatus({
+          level: ServiceStatusLevels.degraded,
+        }),
+        b: createStatus({
+          level: ServiceStatusLevels.available,
+        }),
+      });
+      const stop$ = hot<void>('----(s|)');
+      const expected = '--a-|';
+
+      expectObservable(getOverallStatusChanges(overall$, stop$)).toBe(expected, {
+        a: 'Kibana is now degraded',
+      });
+    });
+  });
+});

src/core/server/status/log_overall_status.ts

@@ -0,0 +1,31 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * 2.0 and the Server Side Public License, v 1; you may not use this file except
+ * in compliance with, at your election, the Elastic License 2.0 or the Server
+ * Side Public License, v 1.
+ */
+
+import { Observable } from 'rxjs';
+import { distinctUntilChanged, pairwise, startWith, takeUntil, map } from 'rxjs/operators';
+import { ServiceStatus } from './types';
+
+export const getOverallStatusChanges = (
+  overall$: Observable<ServiceStatus>,
+  stop$: Observable<void>
+) => {
+  return overall$.pipe(
+    takeUntil(stop$),
+    distinctUntilChanged((previous, next) => {
+      return previous.level.toString() === next.level.toString();
+    }),
+    startWith(undefined),
+    pairwise(),
+    map(([oldStatus, newStatus]) => {
+      if (oldStatus) {
+        return `Kibana is now ${newStatus!.level.toString()} (was ${oldStatus!.level.toString()})`;
+      }
+      return `Kibana is now ${newStatus!.level.toString()}`;
+    })
+  );
+};

src/core/server/status/plugins_status.test.ts

@@ -301,9 +301,9 @@ describe('PluginStatusService', () => {
       pluginA$.next(available);
       pluginA$.next(degraded);
       // Waiting for the debounce timeout should cut a new update
-      await delay(500);
+      await delay(25);
       pluginA$.next(available);
-      await delay(500);
+      await delay(25);
       subscription.unsubscribe();
 
       expect(statusUpdates).toMatchInlineSnapshot(`

src/core/server/status/plugins_status.ts

@@ -51,7 +51,7 @@ export class PluginsStatusService {
 
     return this.getPluginStatuses$(dependencies).pipe(
       // Prevent many emissions at once from dependency status resolution from making this too noisy
-      debounceTime(500)
+      debounceTime(25)
     );
   }
 

src/core/server/status/status_service.ts

@@ -6,7 +6,7 @@
  * Side Public License, v 1.
  */
 
-import { Observable, combineLatest, Subscription } from 'rxjs';
+import { Observable, combineLatest, Subscription, Subject } from 'rxjs';
 import { map, distinctUntilChanged, shareReplay, take, debounceTime } from 'rxjs/operators';
 import { isDeepStrictEqual } from 'util';
 
@@ -25,6 +25,7 @@ import { config, StatusConfigType } from './status_config';
 import { ServiceStatus, CoreStatus, InternalStatusServiceSetup } from './types';
 import { getSummaryStatus } from './get_summary_status';
 import { PluginsStatusService } from './plugins_status';
+import { getOverallStatusChanges } from './log_overall_status';
 
 interface StatusLogMeta extends LogMeta {
   kibana: { status: ServiceStatus };
@@ -42,7 +43,9 @@ interface SetupDeps {
 export class StatusService implements CoreService<InternalStatusServiceSetup> {
   private readonly logger: Logger;
   private readonly config$: Observable<StatusConfigType>;
+  private readonly stop$ = new Subject<void>();
 
+  private overall$?: Observable<ServiceStatus>;
   private pluginsStatus?: PluginsStatusService;
   private overallSubscription?: Subscription;
 
@@ -63,10 +66,7 @@ export class StatusService implements CoreService<InternalStatusServiceSetup> {
     const core$ = this.setupCoreStatus({ elasticsearch, savedObjects });
     this.pluginsStatus = new PluginsStatusService({ core$, pluginDependencies });
 
-    const overall$: Observable<ServiceStatus> = combineLatest([
-      core$,
-      this.pluginsStatus.getAll$(),
-    ]).pipe(
+    this.overall$ = combineLatest([core$, this.pluginsStatus.getAll$()]).pipe(
       // Prevent many emissions at once from dependency status resolution from making this too noisy
       debounceTime(500),
       map(([coreStatus, pluginsStatus]) => {
@@ -86,7 +86,7 @@ export class StatusService implements CoreService<InternalStatusServiceSetup> {
     );
 
     // Create an unused subscription to ensure all underlying lazy observables are started.
-    this.overallSubscription = overall$.subscribe();
+    this.overallSubscription = this.overall$.subscribe();
 
     const commonRouteDeps = {
       config: {
@@ -97,7 +97,7 @@ export class StatusService implements CoreService<InternalStatusServiceSetup> {
       },
       metrics,
       status: {
-        overall$,
+        overall$: this.overall$,
         plugins$: this.pluginsStatus.getAll$(),
         core$,
       },
@@ -124,7 +124,7 @@ export class StatusService implements CoreService<InternalStatusServiceSetup> {
 
     return {
       core$,
-      overall$,
+      overall$: this.overall$,
       plugins: {
         set: this.pluginsStatus.set.bind(this.pluginsStatus),
         getDependenciesStatus$: this.pluginsStatus.getDependenciesStatus$.bind(this.pluginsStatus),
@@ -134,9 +134,19 @@ export class StatusService implements CoreService<InternalStatusServiceSetup> {
     };
   }
 
-  public start() {}
+  public start() {
+    if (!this.overall$) {
+      throw new Error('cannot call `start` before `setup`');
+    }
+    getOverallStatusChanges(this.overall$, this.stop$).subscribe((message) => {
+      this.logger.info(message);
+    });
+  }
 
   public stop() {
+    this.stop$.next();
+    this.stop$.complete();
+
     if (this.overallSubscription) {
       this.overallSubscription.unsubscribe();
       this.overallSubscription = undefined;

test/functional/apps/bundles/index.js

@@ -18,15 +18,6 @@ export default function ({ getService }) {
 
     let buildNum;
     before(async () => {
-      // Wait for status to become green
-      let status;
-      const start = Date.now();
-      do {
-        const resp = await supertest.get('/api/status');
-        status = resp.status;
-        // Stop polling once status stabilizes OR once 40s has passed
-      } while (status !== 200 && Date.now() - start < 40_000);
-
       const resp = await supertest.get('/api/status').expect(200);
       buildNum = resp.body.version.build_number;
     });

test/server_integration/http/platform/cache.ts

@@ -12,17 +12,6 @@ export default function ({ getService }: FtrProviderContext) {
   const supertest = getService('supertest');
 
   describe('kibana server cache-control', () => {
-    before(async () => {
-      // Wait for status to become green
-      let status;
-      const start = Date.now();
-      do {
-        const resp = await supertest.get('/api/status');
-        status = resp.status;
-        // Stop polling once status stabilizes OR once 40s has passed
-      } while (status !== 200 && Date.now() - start < 40_000);
-    });
-
     it('properly marks responses as private, with directives to disable caching', async () => {
       await supertest
         .get('/api/status')

x-pack/plugins/apm/e2e/run-e2e.sh

@@ -147,7 +147,7 @@ $WAIT_ON_BIN -i 500 -w 500 http-get://admin:changeme@localhost:$KIBANA_PORT/api/
 ## Workaround to wait for the http server running
 ## See: https://github.com/elastic/kibana/issues/66326
 if [ -e kibana.log ] ; then
-    grep -m 1 "http server running" <(tail -f -n +1 kibana.log)
+    grep -m 1 "Kibana is now available" <(tail -f -n +1 kibana.log)
     echo "✅ Kibana server running..."
     grep -m 1 "bundles compiled successfully" <(tail -f -n +1 kibana.log)
     echo "✅ Kibana bundles have been compiled..."

x-pack/plugins/licensing/server/plugin.ts

@@ -32,6 +32,7 @@ import { FeatureUsageService } from './services';
 import { LicenseConfigType } from './licensing_config';
 import { createRouteHandlerContext } from './licensing_route_handler_context';
 import { createOnPreResponseHandler } from './on_pre_response_handler';
+import { getPluginStatus$ } from './plugin_status';
 
 function normalizeServerLicense(license: RawLicense): PublicLicense {
   return {
@@ -80,7 +81,7 @@ function sign({
  * current Kibana instance.
  */
 export class LicensingPlugin implements Plugin<LicensingPluginSetup, LicensingPluginStart, {}, {}> {
-  private stop$ = new Subject();
+  private stop$ = new Subject<void>();
   private readonly logger: Logger;
   private readonly config: LicenseConfigType;
   private loggingSubscription?: Subscription;
@@ -127,6 +128,8 @@ export class LicensingPlugin implements Plugin<LicensingPluginSetup, LicensingPl
       pollingFrequency.asMilliseconds()
     );
 
+    core.status.set(getPluginStatus$(license$, this.stop$.asObservable()));
+
     core.http.registerRouteHandlerContext(
       'licensing',
       createRouteHandlerContext(license$, core.getStartServices)