[Reporting] Promote many debug log events to info (#43241) (#43406)

* [Reporting] Move some log lines out of screenshots/index.ts

* promote some getScreenshots logs from debug to info

* promote some queue lifecycle event logs from debug to info

* Comments and renaming

* more info logging: csv from saved search

* rollback code changes to be done in future PR

* log success above error handling

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

@@ -13,7 +13,7 @@ export const getNumberOfItems = async (
   layout: LayoutInstance,
   logger: Logger
 ): Promise<number> => {
-  logger.debug('determining how many items we have');
+  logger.debug('determining how many rendered items to wait for');
 
   // returns the value of the `itemsCountAttribute` if it's there, otherwise
   // we just count the number of `itemSelector`

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

@@ -26,7 +26,7 @@ export const getScreenshots = async ({
   browser: HeadlessBrowser;
   elementsPositionAndAttributes: ElementsPositionAndAttribute[];
 }): Promise<Screenshot[]> => {
-  logger.debug(`taking screenshots`);
+  logger.info(`taking screenshots`);
 
   const asyncDurationLogger = getAsyncDurationLogger(logger);
   const screenshots: Screenshot[] = [];
@@ -45,7 +45,7 @@ export const getScreenshots = async ({
     });
   }
 
-  logger.debug(`screenshots taken: ${screenshots.length}`);
+  logger.info(`screenshots taken: ${screenshots.length}`);
 
   return screenshots;
 };

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

@@ -41,8 +41,6 @@ export function screenshotsObservableFactory(server: KbnServer) {
     layout,
     browserTimezone,
   }: ScreenshotObservableOpts): Rx.Observable<void> {
-    logger.debug(`Creating browser driver factory`);
-
     const create$ = browserDriverFactory.create({
       viewport: layout.getBrowserViewport(),
       browserTimezone,
@@ -50,7 +48,6 @@ export function screenshotsObservableFactory(server: KbnServer) {
 
     return create$.pipe(
       mergeMap(({ driver$, exit$, message$, consoleMessage$ }) => {
-        logger.debug('Driver factory created');
         message$.subscribe((line: string) => {
           logger.debug(line, ['browser']);
         });
@@ -92,10 +89,8 @@ export function screenshotsObservableFactory(server: KbnServer) {
             ({ browser, itemsCount }) => ({ browser, itemsCount })
           ),
           mergeMap(
-            ({ browser, itemsCount }) => {
-              logger.debug(`waiting for ${itemsCount} to be in the DOM`);
-              return waitForElementsToBeInDOM(browser, itemsCount, layout);
-            },
+            ({ browser, itemsCount }) =>
+              waitForElementsToBeInDOM(browser, itemsCount, layout, logger),
             ({ browser, itemsCount }) => ({ browser, itemsCount })
           ),
           mergeMap(

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

@@ -5,13 +5,17 @@
  */
 
 import { HeadlessChromiumDriver as HeadlessBrowser } from '../../../../server/browsers/chromium/driver';
+import { LevelLogger as Logger } from '../../../../server/lib';
 import { LayoutInstance } from '../../layouts/layout';
 
 export const waitForElementsToBeInDOM = async (
   browser: HeadlessBrowser,
   itemsCount: number,
-  layout: LayoutInstance
-): Promise<void> => {
+  layout: LayoutInstance,
+  logger: Logger
+): Promise<number> => {
+  logger.debug(`waiting for ${itemsCount} rendered elements to be in the DOM`);
+
   await browser.waitFor({
     fn: selector => {
       return document.querySelectorAll(selector).length;
@@ -19,4 +23,7 @@ export const waitForElementsToBeInDOM = async (
     args: [layout.selectors.renderComplete],
     toEqual: itemsCount,
   });
+
+  logger.info(`found ${itemsCount} rendered elements in the DOM`);
+  return itemsCount;
 };

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

@@ -5,9 +5,7 @@
  */
 
 import { CSV_JOB_TYPE, PLUGIN_ID } from '../../../common/constants';
-import { cryptoFactory } from '../../../server/lib/crypto';
-import { oncePerServer } from '../../../server/lib/once_per_server';
-import { LevelLogger } from '../../../server/lib/level_logger';
+import { cryptoFactory, oncePerServer, LevelLogger } from '../../../server/lib';
 import { createGenerateCsv } from './lib/generate_csv';
 import { fieldFormatMapFactory } from './lib/field_format_map';
 import { i18n } from '@kbn/i18n';
@@ -16,7 +14,7 @@ function executeJobFn(server) {
   const { callWithRequest } = server.plugins.elasticsearch.getCluster('data');
   const crypto = cryptoFactory(server);
   const config = server.config();
-  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, CSV_JOB_TYPE]);
+  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, CSV_JOB_TYPE, 'execute-job']);
   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,7 +8,7 @@ import { notFound, notImplemented } from 'boom';
 import { Request } from 'hapi';
 import { get } from 'lodash';
 
-import { PLUGIN_ID } from '../../../../common/constants';
+import { PLUGIN_ID, CSV_FROM_SAVEDOBJECT_JOB_TYPE } from '../../../../common/constants';
 import { cryptoFactory, LevelLogger, oncePerServer } from '../../../../server/lib';
 import { JobDocPayload, JobParams, KbnServer } from '../../../../types';
 import {
@@ -31,7 +31,11 @@ type CreateJobFn = (jobParams: JobParams, headers: any, req: Request) => Promise
 
 function createJobFn(server: KbnServer): CreateJobFn {
   const crypto = cryptoFactory(server);
-  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, 'savedobject-csv']);
+  const logger = LevelLogger.createForServer(server, [
+    PLUGIN_ID,
+    CSV_FROM_SAVEDOBJECT_JOB_TYPE,
+    'create-job',
+  ]);
 
   return async function createJob(
     jobParams: JobParams,

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

@@ -9,7 +9,11 @@ import { i18n } from '@kbn/i18n';
 
 import { cryptoFactory, LevelLogger, oncePerServer } from '../../../server/lib';
 import { JobDocOutputExecuted, JobDocPayload, KbnServer } from '../../../types';
-import { CONTENT_TYPE_CSV, PLUGIN_ID } from '../../../common/constants';
+import {
+  CONTENT_TYPE_CSV,
+  CSV_FROM_SAVEDOBJECT_JOB_TYPE,
+  PLUGIN_ID,
+} from '../../../common/constants';
 import { CsvResultFromSearch, createGenerateCsv } from './lib';
 
 interface FakeRequest {
@@ -20,11 +24,15 @@ interface FakeRequest {
 
 type ExecuteJobFn = (job: JobDocPayload, realRequest?: Request) => Promise<JobDocOutputExecuted>;
 
-function executeJobFn(server: KbnServer): ExecuteJobFn {
+function executeJobFactoryFn(server: KbnServer): ExecuteJobFn {
   const crypto = cryptoFactory(server);
   const config = server.config();
   const serverBasePath = config.get('server.basePath');
-  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, 'savedobject-csv']);
+  const logger = LevelLogger.createForServer(server, [
+    PLUGIN_ID,
+    CSV_FROM_SAVEDOBJECT_JOB_TYPE,
+    'execute-job',
+  ]);
   const generateCsv = createGenerateCsv(logger);
 
   return async function executeJob(
@@ -38,10 +46,10 @@ function executeJobFn(server: KbnServer): ExecuteJobFn {
 
     let requestObject: Request | FakeRequest;
     if (isImmediate && realRequest) {
-      logger.debug(`executing job from immediate API`);
+      logger.info(`Executing job from immediate API`);
       requestObject = realRequest;
     } else {
-      logger.debug(`executing job async using encrypted headers`);
+      logger.info(`Executing job async using encrypted headers`);
       let decryptedHeaders;
       const serializedEncryptedHeaders = job.headers;
       try {
@@ -99,4 +107,4 @@ function executeJobFn(server: KbnServer): ExecuteJobFn {
   };
 }
 
-export const executeJobFactory = oncePerServer(executeJobFn);
+export const executeJobFactory = oncePerServer(executeJobFactoryFn);

x-pack/legacy/plugins/reporting/export_types/png/server/lib/generate_png.ts

@@ -24,11 +24,9 @@ interface UrlScreenshot {
 function generatePngObservableFn(server: KbnServer) {
   const screenshotsObservable = screenshotsObservableFactory(server);
   const captureConcurrency = 1;
-  const createPngWithScreenshots = async ({
-    urlScreenshots,
-  }: {
-    urlScreenshots: UrlScreenshot[];
-  }) => {
+
+  // prettier-ignore
+  const createPngWithScreenshots = async ({ urlScreenshots }: { urlScreenshots: UrlScreenshot[] }) => {
     if (urlScreenshots.length !== 1) {
       throw new Error(
         `Expected there to be 1 URL screenshot, but there are ${urlScreenshots.length}`

x-pack/legacy/plugins/reporting/server/browsers/chromium/driver/chromium_driver.ts

@@ -45,9 +45,11 @@ export class HeadlessChromiumDriver {
       waitForSelector,
     }: { conditionalHeaders: ConditionalHeaders; waitForSelector: string }
   ) {
-    this.logger.debug(`opening url ${url}`);
+    this.logger.info(`opening url ${url}`);
     await this.page.setRequestInterception(true);
+    let interceptedCount = 0;
     this.page.on('request', (interceptedRequest: any) => {
+      let isData = false;
       if (this._shouldUseCustomHeaders(conditionalHeaders.conditions, interceptedRequest.url())) {
         this.logger.debug(`Using custom headers for ${interceptedRequest.url()}`);
         interceptedRequest.continue({
@@ -58,17 +60,22 @@ export class HeadlessChromiumDriver {
         });
       } else {
         let interceptedUrl = interceptedRequest.url();
+
         if (interceptedUrl.startsWith('data:')) {
           // `data:image/xyz;base64` can be very long URLs
           interceptedUrl = interceptedUrl.substring(0, 100) + '[truncated]';
+          isData = true;
         }
+
         this.logger.debug(`No custom headers for ${interceptedUrl}`);
         interceptedRequest.continue();
       }
+      interceptedCount = interceptedCount + (isData ? 0 : 1);
     });
 
     await this.page.goto(url, { waitUntil: 'domcontentloaded' });
     await this.waitForSelector(waitForSelector);
+    this.logger.info(`handled ${interceptedCount} page requests`);
   }
 
   public async screenshot(elementPosition: ElementPosition) {

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

@@ -13,11 +13,11 @@ import * as Rx from 'rxjs';
 import { map, share, mergeMap, filter, partition, ignoreElements, tap } from 'rxjs/operators';
 import { InnerSubscriber } from 'rxjs/internal/InnerSubscriber';
 
+import { LevelLogger as Logger } from '../../../lib/level_logger';
 import { HeadlessChromiumDriver } from '../driver';
 import { args, IArgOptions } from './args';
 import { safeChildProcess } from '../../safe_child_process';
 import { getChromeLogLocation } from '../paths';
-import { Logger } from '../../../../types';
 
 type binaryPath = string;
 type queueTimeout = number;
@@ -31,27 +31,27 @@ const compactWhitespace = (str: string) => {
 
 export class HeadlessChromiumDriverFactory {
   private binaryPath: binaryPath;
-  private callerLogger: Logger;
+  private logger: Logger;
   private browserConfig: IBrowserConfig;
   private queueTimeout: queueTimeout;
 
   constructor(
     binaryPath: binaryPath,
-    logger: any,
+    logger: Logger,
     browserConfig: IBrowserConfig,
     queueTimeout: queueTimeout
   ) {
     this.binaryPath = binaryPath;
     this.browserConfig = browserConfig;
     this.queueTimeout = queueTimeout;
-    this.callerLogger = logger;
+    this.logger = logger;
   }
 
   type = 'chromium';
 
   test(
     { viewport, browserTimezone }: { viewport: IArgOptions['viewport']; browserTimezone: string },
-    logger: any
+    logger: Logger
   ) {
     const userDataDir = fs.mkdtempSync(path.join(os.tmpdir(), 'chromium-'));
     const chromiumArgs = args({
@@ -94,11 +94,13 @@ export class HeadlessChromiumDriverFactory {
     exit$: Rx.Observable<never>;
   }> {
     return Rx.Observable.create(async (observer: InnerSubscriber<any, any>) => {
+      this.logger.debug(`Creating browser driver factory`);
+
       const userDataDir = fs.mkdtempSync(path.join(os.tmpdir(), 'chromium-'));
       const chromiumArgs = args({
         userDataDir,
         viewport,
-        verboseLogging: this.callerLogger.isVerbose,
+        verboseLogging: this.logger.isVerbose,
         disableSandbox: this.browserConfig.disableSandbox,
         proxyConfig: this.browserConfig.proxy,
       });
@@ -125,6 +127,8 @@ export class HeadlessChromiumDriverFactory {
         // "TimeoutError: waiting for selector ".application" failed: timeout 30000ms exceeded"
         // @ts-ignore outdated typedefs for puppteer
         page.setDefaultTimeout(this.queueTimeout);
+
+        this.logger.debug(`Browser driver factory created`);
       } catch (err) {
         observer.error(new Error(`Error spawning Chromium browser: [${err}]`));
         throw err;
@@ -135,14 +139,12 @@ export class HeadlessChromiumDriverFactory {
           await browser.close();
         },
       };
-      const { terminate$ } = safeChildProcess(this.callerLogger, childProcess);
+      const { terminate$ } = safeChildProcess(this.logger, childProcess);
 
       // this is adding unsubscribe logic to our observer
       // so that if our observer unsubscribes, we terminate our child-process
       observer.add(() => {
-        this.callerLogger.debug(
-          `The browser process observer has unsubscribed. Closing the browser...`
-        );
+        this.logger.debug(`The browser process observer has unsubscribed. Closing the browser...`);
         childProcess.kill(); // ignore async
       });
 
@@ -151,7 +153,7 @@ export class HeadlessChromiumDriverFactory {
         terminate$
           .pipe(
             tap(signal => {
-              this.callerLogger.debug(`Observer got signal: ${signal}`);
+              this.logger.debug(`Observer got signal: ${signal}`);
             }),
             ignoreElements()
           )
@@ -174,7 +176,7 @@ export class HeadlessChromiumDriverFactory {
 
       const driver$ = Rx.of(
         new HeadlessChromiumDriver(page, {
-          logger: this.callerLogger,
+          logger: this.logger,
         })
       );
 
@@ -249,7 +251,7 @@ export class HeadlessChromiumDriverFactory {
         exit$,
       });
 
-      const factoryLogger = this.callerLogger.clone(['chromium-driver-factory']);
+      const factoryLogger = this.logger.clone(['chromium-driver-factory']);
       // unsubscribe logic makes a best-effort attempt to delete the user data directory used by chromium
       observer.add(() => {
         factoryLogger.debug(`deleting chromium user data directory at [${userDataDir}]`);

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

@@ -4,7 +4,6 @@
  * you may not use this file except in compliance with the Elastic License.
  */
 
-// @ts-ignore
 import { PLUGIN_ID } from '../../common/constants';
 import {
   ESQueueInstance,
@@ -16,7 +15,6 @@ import {
 } from '../../types';
 // @ts-ignore untyped dependency
 import { events as esqueueEvents } from './esqueue';
-// @ts-ignore untyped dependency
 import { LevelLogger } from './level_logger';
 // @ts-ignore untyped dependency
 import { oncePerServer } from './once_per_server';
@@ -27,7 +25,7 @@ function createWorkerFn(server: KbnServer) {
   const kibanaName = config.get('server.name');
   const kibanaId = config.get('server.uuid');
   const exportTypesRegistry = server.plugins.reporting.exportTypesRegistry;
-  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, 'queue', 'worker']);
+  const logger = LevelLogger.createForServer(server, [PLUGIN_ID, 'queue', 'create-worker']);
 
   // Once more document types are added, this will need to be passed in
   return function createWorker(queue: ESQueueInstance) {

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

@@ -31,7 +31,7 @@ function enqueueJobFn(server) {
 
       job.on(esqueueEvents.EVENT_JOB_CREATED, (createdJob) => {
         if (createdJob.id === job.id) {
-          server.log(['reporting', 'debug'], `Saved object to process`);
+          server.log(['reporting', 'esqueue', 'info'], `Successfully queued job: ${createdJob.id}`);
           resolve(job);
         }
       });

x-pack/legacy/plugins/reporting/server/lib/esqueue/worker.js

@@ -27,8 +27,11 @@ const MAX_ERROR_LENGTH = (MAX_PARTIAL_ERROR_LENGTH * 2) + ERROR_PARTIAL_SEPARATO
 
 function getLogger(opts, id, logLevel) {
   return (msg, err) => {
+    /*
+     * This does not get the logger instance from queue.registerWorker in the createWorker function.
+     * The logger instance in the Equeue lib comes from createTaggedLogger, so logLevel tags are passed differently
+     */
     const logger = opts.logger || function () {};
-
     const message = `${id} - ${msg}`;
     const tags = ['worker', logLevel];
 
@@ -81,6 +84,7 @@ export class Worker extends events.EventEmitter {
 
     this.debug = getLogger(opts, this.id, 'debug');
     this.warn = getLogger(opts, this.id, 'warn');
+    this.info = getLogger(opts, this.id, 'info');
 
     this._running = true;
     this.debug(`Created worker for ${this.jobtype} jobs`);
@@ -219,7 +223,7 @@ export class Worker extends events.EventEmitter {
   }
 
   _performJob(job) {
-    this.debug(`Starting job ${job._id}`);
+    this.info(`Starting job`);
 
     const workerOutput = new Promise((resolve, reject) => {
       // run the worker's workerFn
@@ -229,6 +233,9 @@ export class Worker extends events.EventEmitter {
 
       Promise.resolve(this.workerFn.call(null, job, jobSource.payload, cancellationToken))
         .then(res => {
+          // job execution was successful
+          this.info(`Job execution completed successfully`);
+
           isResolved = true;
           resolve(res);
         })
@@ -254,8 +261,6 @@ export class Worker extends events.EventEmitter {
     });
 
     return workerOutput.then((output) => {
-      // job execution was successful
-      this.debug(`Completed job ${job._id}`);
 
       const completedTime = moment().toISOString();
       const docOutput = this._formatOutput(output);
@@ -273,13 +278,16 @@ export class Worker extends events.EventEmitter {
         if_primary_term: job._primary_term,
         body: { doc }
       })
-        .then(() => {
+        .then((response) => {
           const eventOutput = {
             job: formatJobObject(job),
             output: docOutput,
           };
-
           this.emit(constants.EVENT_WORKER_COMPLETE, eventOutput);
+
+          const formattedDocPath = `/${response._index}/${response._type}/${response._id}`;
+          this.info(`Job data saved successfully: ${formattedDocPath}`);
+          return response;
         })
         .catch((err) => {
           if (err.statusCode === 409) return false;
@@ -365,7 +373,7 @@ export class Worker extends events.EventEmitter {
           this.debug(`Found no claimable jobs out of ${jobs.length} total`);
           return;
         }
-        this.debug(`Claimed job ${claimedJob._id}`);
+        this.info(`Claimed job ${claimedJob._id}`);
         return this._performJob(claimedJob);
       })
       .catch((err) => {

x-pack/legacy/plugins/reporting/server/routes/generate_from_savedobject_immediate.ts

@@ -44,6 +44,8 @@ export function registerGenerateCsvFromSavedObjectImmediate(
       const logger = parentLogger.clone(['savedobject-csv']);
       const jobParams = getJobParamsFromRequest(request, { isImmediate: true });
       const createJobFn = createJobFactory(server);
+      // By passing the request, we signal this as an "immediate" job.
+      // TODO: use a different executeFn for immediate, with a different call signature, to clean up messy types
       const executeJobFn = executeJobFactory(server, request);
       const jobDocPayload: JobDocPayload = await createJobFn(jobParams, request.headers, request);
       const {
@@ -52,7 +54,7 @@ export function registerGenerateCsvFromSavedObjectImmediate(
         size: jobOutputSize,
       }: JobDocOutputExecuted = await executeJobFn(jobDocPayload, request);
 
-      logger.info(`job output size: ${jobOutputSize} bytes`);
+      logger.info(`Job output size: ${jobOutputSize} bytes`);
 
       /*
        * ESQueue worker function defaults `content` to null, even if the