[Reporting] Clean up logging, add logging to safeChildProcess (#41727) (

#42270)

* exportTypesRegistry and browserFactory init parallel

* validateConfig to typescript

* ditch `implements Logger`

* move some code around in create_queue

* import LevelLogger in places

* LevelLogger parity, unused `_verbose` ?

* use parentLogger.clone more

* add logging to safeChildProcess

* fix some ts failures

* do not change the log tags

* back out changes that I dont understand

* pr feedback of using constant for logging tags (when convenient)

* fix import path

* dont log all the headless stuff with the factory tag

* fix constants import

x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots.js

@@ -9,6 +9,7 @@ import { first, tap, mergeMap } from 'rxjs/operators';
 import fs from 'fs';
 import getPort from 'get-port';
 import { promisify } from 'util';
+import { PLUGIN_ID } from '../../../common/constants';
 import { LevelLogger } from '../../../server/lib/level_logger';
 import { i18n } from '@kbn/i18n';
 
@@ -18,7 +19,7 @@ const fsp = {
 
 export function screenshotsObservableFactory(server) {
   const config = server.config();
-  const logger = LevelLogger.createForServer(server, ['reporting', 'screenshots']);
+  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, 'screenshots']);
 
   const browserDriverFactory = server.plugins.reporting.browserDriverFactory;
   const captureConfig = config.get('xpack.reporting.capture');

x-pack/legacy/plugins/reporting/export_types/csv/server/execute_job.js

@@ -4,9 +4,10 @@
  * you may not use this file except in compliance with the Elastic License.
  */
 
+import { CSV_JOB_TYPE, PLUGIN_ID } from '../../../common/constants';
 import { cryptoFactory } from '../../../server/lib/crypto';
 import { oncePerServer } from '../../../server/lib/once_per_server';
-import { createTaggedLogger } from '../../../server/lib/create_tagged_logger';
+import { LevelLogger } from '../../../server/lib/level_logger';
 import { createGenerateCsv } from './lib/generate_csv';
 import { fieldFormatMapFactory } from './lib/field_format_map';
 import { i18n } from '@kbn/i18n';
@@ -15,10 +16,7 @@ function executeJobFn(server) {
   const { callWithRequest } = server.plugins.elasticsearch.getCluster('data');
   const crypto = cryptoFactory(server);
   const config = server.config();
-  const logger = {
-    debug: createTaggedLogger(server, ['reporting', 'csv', 'debug']),
-    warn: createTaggedLogger(server, ['reporting', 'csv', 'warning']),
-  };
+  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, CSV_JOB_TYPE]);
   const generateCsv = createGenerateCsv(logger);
   const serverBasePath = config.get('server.basePath');
 

x-pack/legacy/plugins/reporting/export_types/csv_from_savedobject/server/create_job/create_job.ts

@@ -8,6 +8,7 @@ import { notFound, notImplemented } from 'boom';
 import { Request } from 'hapi';
 import { get } from 'lodash';
 
+import { PLUGIN_ID } from '../../../../common/constants';
 import { cryptoFactory, LevelLogger, oncePerServer } from '../../../../server/lib';
 import { JobDocPayload, JobParams, KbnServer } from '../../../../types';
 import {
@@ -30,7 +31,7 @@ type CreateJobFn = (jobParams: JobParams, headers: any, req: Request) => Promise
 
 function createJobFn(server: KbnServer): CreateJobFn {
   const crypto = cryptoFactory(server);
-  const logger = LevelLogger.createForServer(server, ['reporting', 'savedobject-csv']);
+  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, 'savedobject-csv']);
 
   return async function createJob(
     jobParams: JobParams,

x-pack/legacy/plugins/reporting/export_types/csv_from_savedobject/server/execute_job.ts

@@ -9,7 +9,7 @@ import { i18n } from '@kbn/i18n';
 
 import { cryptoFactory, LevelLogger, oncePerServer } from '../../../server/lib';
 import { JobDocOutputExecuted, JobDocPayload, KbnServer } from '../../../types';
-import { CONTENT_TYPE_CSV } from '../../../common/constants';
+import { CONTENT_TYPE_CSV, PLUGIN_ID } from '../../../common/constants';
 import { CsvResultFromSearch, createGenerateCsv } from './lib';
 
 interface FakeRequest {
@@ -24,7 +24,7 @@ function executeJobFn(server: KbnServer): ExecuteJobFn {
   const crypto = cryptoFactory(server);
   const config = server.config();
   const serverBasePath = config.get('server.basePath');
-  const logger = LevelLogger.createForServer(server, ['reporting', 'savedobject-csv']);
+  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, 'savedobject-csv']);
   const generateCsv = createGenerateCsv(logger);
 
   return async function executeJob(

x-pack/legacy/plugins/reporting/export_types/printable_pdf/server/create_job/compatibility_shim.js

@@ -5,11 +5,12 @@
  */
 
 import { uriEncode } from '../lib/uri_encode';
+import { PLUGIN_ID } from '../../../../common/constants';
 
 export function compatibilityShimFactory(server) {
 
   const logDeprecation = (msg) => {
-    server.log(['warning', 'reporting', 'deprecation'], msg + ' This functionality will be removed with the next major version.');
+    server.log(['warning', PLUGIN_ID, 'deprecation'], msg + ' This functionality will be removed with the next major version.');
   };
 
   const getSavedObjectTitle = async (objectType, savedObjectId, savedObjectsClient) => {

x-pack/legacy/plugins/reporting/index.js

@@ -8,13 +8,19 @@ import { resolve } from 'path';
 import { PLUGIN_ID, UI_SETTINGS_CUSTOM_PDF_LOGO } from './common/constants';
 import { mirrorPluginStatus } from '../../server/lib/mirror_plugin_status';
 import { registerRoutes } from './server/routes';
-
-import { createQueueFactory } from './server/lib/create_queue';
+import {
+  LevelLogger,
+  checkLicenseFactory,
+  createQueueFactory,
+  exportTypesRegistryFactory,
+  runValidations,
+} from './server/lib';
 import { config as appConfig } from './server/config/config';
-import { checkLicenseFactory } from './server/lib/check_license';
-import { runValidations } from './server/lib/validate';
-import { exportTypesRegistryFactory } from './server/lib/export_types_registry';
-import { CHROMIUM, createBrowserDriverFactory, getDefaultChromiumSandboxDisabled } from './server/browsers';
+import {
+  CHROMIUM,
+  createBrowserDriverFactory,
+  getDefaultChromiumSandboxDisabled,
+} from './server/browsers';
 import { logConfiguration } from './log_configuration';
 
 import { getReportingUsageCollector } from './server/usage';
@@ -158,15 +164,14 @@ export const reporting = (kibana) => {
       // Register a function with server to manage the collection of usage stats
       server.usage.collectorSet.register(getReportingUsageCollector(server, isReady));
 
-      const exportTypesRegistry = await exportTypesRegistryFactory(server);
-      const browserFactory = await createBrowserDriverFactory(server);
+      const logger = LevelLogger.createForServer(server, [PLUGIN_ID], true);
+      const [exportTypesRegistry, browserFactory] = await Promise.all([
+        exportTypesRegistryFactory(server),
+        createBrowserDriverFactory(server),
+      ]);
       server.expose('exportTypesRegistry', exportTypesRegistry);
 
       const config = server.config();
-      const logger = {
-        debug: message => server.log(['reporting', 'debug'], message),
-        warning: message => server.log(['reporting', 'warning'], message),
-      };
       logConfiguration(config, logger);
       runValidations(server, config, logger, browserFactory);
 
@@ -186,7 +191,7 @@ export const reporting = (kibana) => {
       server.expose('queue', createQueueFactory(server));
 
       // Reporting routes
-      registerRoutes(server);
+      registerRoutes(server, logger);
     },
 
     deprecations: function ({ unused }) {

x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts

@@ -31,7 +31,7 @@ const compactWhitespace = (str: string) => {
 
 export class HeadlessChromiumDriverFactory {
   private binaryPath: binaryPath;
-  private logger: Logger;
+  private callerLogger: Logger;
   private browserConfig: IBrowserConfig;
   private queueTimeout: queueTimeout;
 
@@ -42,9 +42,9 @@ export class HeadlessChromiumDriverFactory {
     queueTimeout: queueTimeout
   ) {
     this.binaryPath = binaryPath;
-    this.logger = logger.clone(['chromium-driver-factory']);
     this.browserConfig = browserConfig;
     this.queueTimeout = queueTimeout;
+    this.callerLogger = logger;
   }
 
   type = 'chromium';
@@ -93,7 +93,7 @@ export class HeadlessChromiumDriverFactory {
       const chromiumArgs = args({
         userDataDir,
         viewport,
-        verboseLogging: this.logger.isVerbose,
+        verboseLogging: this.callerLogger.isVerbose,
         disableSandbox: this.browserConfig.disableSandbox,
         proxyConfig: this.browserConfig.proxy,
       });
@@ -126,6 +126,7 @@ export class HeadlessChromiumDriverFactory {
       }
 
       safeChildProcess(
+        this.callerLogger,
         {
           async kill() {
             await browser.close();
@@ -150,7 +151,7 @@ export class HeadlessChromiumDriverFactory {
 
       const driver$ = Rx.of(
         new HeadlessChromiumDriver(page, {
-          logger: this.logger,
+          logger: this.callerLogger,
         })
       );
 
@@ -225,14 +226,15 @@ export class HeadlessChromiumDriverFactory {
         exit$,
       });
 
+      const factoryLogger = this.callerLogger.clone(['chromium-driver-factory']);
       // unsubscribe logic makes a best-effort attempt to delete the user data directory used by chromium
       observer.add(() => {
-        this.logger.debug(`deleting chromium user data directory at [${userDataDir}]`);
+        factoryLogger.debug(`deleting chromium user data directory at [${userDataDir}]`);
         // the unsubscribe function isn't `async` so we're going to make our best effort at
         // deleting the userDataDir and if it fails log an error.
         rimraf(userDataDir, err => {
           if (err) {
-            return this.logger.error(
+            return factoryLogger.error(
               `error deleting user data directory at [${userDataDir}]: [${err}]`
             );
           }

x-pack/legacy/plugins/reporting/server/browsers/safe_child_process.ts

@@ -7,14 +7,19 @@
 import * as Rx from 'rxjs';
 import { take, share, mapTo, delay, tap, ignoreElements } from 'rxjs/operators';
 import { InnerSubscriber } from 'rxjs/internal/InnerSubscriber';
+import { Logger } from '../../types';
 
 interface IChild {
   kill: (signal: string) => Promise<any>;
 }
 
 // Our process can get sent various signals, and when these occur we wish to
 // kill the subprocess and then kill our process as long as the observer isn't cancelled
-export function safeChildProcess(childProcess: IChild, observer: InnerSubscriber<any, any>) {
+export function safeChildProcess(
+  logger: Logger,
+  childProcess: IChild,
+  observer: InnerSubscriber<any, any>
+): void {
   const ownTerminateSignal$ = Rx.merge(
     Rx.fromEvent(process as NodeJS.EventEmitter, 'SIGTERM').pipe(mapTo('SIGTERM')),
     Rx.fromEvent(process as NodeJS.EventEmitter, 'SIGINT').pipe(mapTo('SIGINT')),
@@ -50,17 +55,9 @@ export function safeChildProcess(childProcess: IChild, observer: InnerSubscriber
   // this is adding unsubscribe logic to our observer
   // so that if our observer unsubscribes, we terminate our child-process
   observer.add(() => {
+    logger.debug(`The browser process observer has unsubscribed. Closing the browser...`);
     childProcess.kill('SIGKILL');
   });
 
   observer.add(terminate$.pipe(ignoreElements()).subscribe(observer));
 }
-
-// If a process exits ungracefully, we can try to help the user make sense of why
-// by giving them a suggestion based on the code.
-export function exitCodeSuggestion(code: number | null) {
-  if (code === null) {
-    return 'Your report may be too large. Try removing some visualizations or increasing the RAM available to Kibana.';
-  }
-  return '';
-}

x-pack/legacy/plugins/reporting/server/lib/create_queue.js

@@ -4,34 +4,34 @@
  * you may not use this file except in compliance with the Elastic License.
  */
 
+import { PLUGIN_ID } from '../../common/constants';
 import { Esqueue } from './esqueue';
 import { createWorkerFactory } from './create_worker';
 import { oncePerServer } from './once_per_server';
-import { createTaggedLogger } from './create_tagged_logger';
-
-const dateSeparator = '.';
+import { LevelLogger } from './level_logger';
+import { createTaggedLogger } from './create_tagged_logger'; // TODO remove createTaggedLogger once esqueue is removed
 
 function createQueueFn(server) {
   const queueConfig = server.config().get('xpack.reporting.queue');
   const index = server.config().get('xpack.reporting.index');
-  const createWorker = createWorkerFactory(server);
 
-  const logger = createTaggedLogger(server, ['reporting', 'esqueue']);
   const queueOptions = {
     interval: queueConfig.indexInterval,
     timeout: queueConfig.timeout,
-    dateSeparator: dateSeparator,
+    dateSeparator: '.',
     client: server.plugins.elasticsearch.getCluster('admin'),
-    logger,
+    logger: createTaggedLogger(server, [PLUGIN_ID, 'esqueue']),
   };
 
   const queue = new Esqueue(index, queueOptions);
 
   if (queueConfig.pollEnabled) {
     // create workers to poll the index for idle jobs waiting to be claimed and executed
+    const createWorker = createWorkerFactory(server);
     createWorker(queue);
   } else {
-    logger(
+    const logger = LevelLogger.createForServer(server, [PLUGIN_ID, 'create_queue']);
+    logger.info(
       'xpack.reporting.queue.pollEnabled is set to false. This Kibana instance ' +
       'will not poll for idle jobs to claim and execute. Make sure another ' +
       'Kibana instance with polling enabled is running in this cluster so ' +

x-pack/legacy/plugins/reporting/server/lib/export_types_registry.js

@@ -6,8 +6,9 @@
 
 import { resolve } from 'path';
 import glob from 'glob';
+import { PLUGIN_ID } from '../../common/constants';
 import { ExportTypesRegistry } from '../../common/export_types_registry';
-import { oncePerServer } from './once_per_server';
+import { oncePerServer, LevelLogger } from './';
 
 function scan(pattern) {
   return new Promise((resolve, reject) => {
@@ -23,10 +24,12 @@ function scan(pattern) {
 
 const pattern = resolve(__dirname, '../../export_types/*/server/index.[jt]s');
 async function exportTypesRegistryFn(server) {
+  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, 'exportTypes']);
   const exportTypesRegistry = new ExportTypesRegistry();
   const files = await scan(pattern);
+
   files.forEach(file => {
-    server.log(['reporting', 'debug', 'exportTypes'], `Found exportType at ${file}`);
+    logger.debug(`Found exportType at ${file}`);
 
     const { register } = require(file); // eslint-disable-line import/no-dynamic-require
     register(exportTypesRegistry);

x-pack/legacy/plugins/reporting/server/lib/index.ts

@@ -4,11 +4,16 @@
  * you may not use this file except in compliance with the Elastic License.
  */
 
-// @ts-ignore untyped module
-export { createTaggedLogger } from './create_tagged_logger';
 // @ts-ignore untyped module
 export { cryptoFactory } from './crypto';
 // @ts-ignore untyped module
 export { oncePerServer } from './once_per_server';
+// @ts-ignore untyped module
+export { createQueueFactory } from './create_queue';
+// @ts-ignore untyped module
+export { exportTypesRegistryFactory } from './export_types_registry';
+// @ts-ignore untyped module
+export { checkLicenseFactory } from './check_license';
 
 export { LevelLogger } from './level_logger';
+export { runValidations } from './validate';

x-pack/legacy/plugins/reporting/server/lib/level_logger.ts

@@ -4,24 +4,24 @@
  * you may not use this file except in compliance with the Elastic License.
  */
 
-import { Logger } from '../../types';
-
 type ServerLog = (tags: string[], msg: string) => void;
 
-export class LevelLogger implements Logger {
+export class LevelLogger {
   private _logger: any;
   private _tags: string[];
+  private _isVerbose: boolean;
 
   public warn: (msg: string, tags?: string[]) => void;
 
-  static createForServer(server: any, tags: string[]) {
+  static createForServer(server: any, tags: string[], isVerbose = false) {
     const serverLog: ServerLog = (tgs: string[], msg: string) => server.log(tgs, msg);
-    return new LevelLogger(serverLog, tags);
+    return new LevelLogger(serverLog, tags, isVerbose);
   }
 
-  constructor(logger: ServerLog, tags: string[]) {
+  constructor(logger: ServerLog, tags: string[], isVerbose: boolean) {
     this._logger = logger;
     this._tags = tags;
+    this._isVerbose = isVerbose;
 
     /*
      * This shortcut provides maintenance convenience: Reporting code has been
@@ -46,7 +46,11 @@ export class LevelLogger implements Logger {
     this._logger([...this._tags, ...tags, 'info'], msg);
   }
 
+  public get isVerbose() {
+    return this._isVerbose;
+  }
+
   public clone(tags: string[]) {
-    return new LevelLogger(this._logger, [...this._tags, ...tags]);
+    return new LevelLogger(this._logger, [...this._tags, ...tags], this._isVerbose);
   }
 }

x-pack/legacy/plugins/reporting/server/lib/validate/index.ts

@@ -13,9 +13,11 @@ import { validateMaxContentLength } from './validate_max_content_length';
 export async function runValidations(
   server: KbnServer,
   config: ConfigObject,
-  logger: Logger,
+  parentLogger: Logger,
   browserFactory: any
 ) {
+  const logger = parentLogger.clone(['self_check']);
+
   try {
     await Promise.all([
       validateBrowser(server, browserFactory, logger),