diff --git a/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/get_number_of_items.ts b/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/get_number_of_items.ts index 99fb4e057c058..e34c5ee00dd48 100644 --- a/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/get_number_of_items.ts +++ b/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 => { - 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` diff --git a/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/get_screenshots.ts b/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/get_screenshots.ts index caa01d2651ca5..3d54650099475 100644 --- a/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/get_screenshots.ts +++ b/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 => { - 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; }; diff --git a/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/index.ts b/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/index.ts index 9fc945b7edb55..919fb6f2cf35c 100644 --- a/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/index.ts +++ b/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 { - 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( diff --git a/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/wait_for_dom_elements.ts b/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/wait_for_dom_elements.ts index 206c03e1012c4..e9ed74c0bb436 100644 --- a/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/wait_for_dom_elements.ts +++ b/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 => { + layout: LayoutInstance, + logger: Logger +): Promise => { + 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; }; diff --git a/x-pack/legacy/plugins/reporting/export_types/csv/server/execute_job.js b/x-pack/legacy/plugins/reporting/export_types/csv/server/execute_job.js index 02f3d82cd87b8..c0366d867b6b8 100644 --- a/x-pack/legacy/plugins/reporting/export_types/csv/server/execute_job.js +++ b/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'); diff --git a/x-pack/legacy/plugins/reporting/export_types/csv_from_savedobject/server/create_job/create_job.ts b/x-pack/legacy/plugins/reporting/export_types/csv_from_savedobject/server/create_job/create_job.ts index 537540b6bfbd3..7b25884a39299 100644 --- a/x-pack/legacy/plugins/reporting/export_types/csv_from_savedobject/server/create_job/create_job.ts +++ b/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, diff --git a/x-pack/legacy/plugins/reporting/export_types/csv_from_savedobject/server/execute_job.ts b/x-pack/legacy/plugins/reporting/export_types/csv_from_savedobject/server/execute_job.ts index a4352f0eae1b5..91f608d0f2a55 100644 --- a/x-pack/legacy/plugins/reporting/export_types/csv_from_savedobject/server/execute_job.ts +++ b/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; -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); diff --git a/x-pack/legacy/plugins/reporting/export_types/png/server/lib/generate_png.ts b/x-pack/legacy/plugins/reporting/export_types/png/server/lib/generate_png.ts index 28eba6b564339..4f67227a17ac7 100644 --- a/x-pack/legacy/plugins/reporting/export_types/png/server/lib/generate_png.ts +++ b/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}` diff --git a/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver/chromium_driver.ts b/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver/chromium_driver.ts index c444e67285a28..a6bd065e991e6 100644 --- a/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver/chromium_driver.ts +++ b/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) { diff --git a/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts b/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts index 49115436f7189..fac946e993190 100644 --- a/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts +++ b/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; }> { return Rx.Observable.create(async (observer: InnerSubscriber) => { + 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}]`); diff --git a/x-pack/legacy/plugins/reporting/server/lib/create_worker.ts b/x-pack/legacy/plugins/reporting/server/lib/create_worker.ts index 5ba45a3599889..670587f680d33 100644 --- a/x-pack/legacy/plugins/reporting/server/lib/create_worker.ts +++ b/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) { diff --git a/x-pack/legacy/plugins/reporting/server/lib/enqueue_job.js b/x-pack/legacy/plugins/reporting/server/lib/enqueue_job.js index 0bd25e6265fd3..cde06262d5996 100644 --- a/x-pack/legacy/plugins/reporting/server/lib/enqueue_job.js +++ b/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); } }); diff --git a/x-pack/legacy/plugins/reporting/server/lib/esqueue/worker.js b/x-pack/legacy/plugins/reporting/server/lib/esqueue/worker.js index eb9cabc3a8e36..3bc7589a374dc 100644 --- a/x-pack/legacy/plugins/reporting/server/lib/esqueue/worker.js +++ b/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) => { diff --git a/x-pack/legacy/plugins/reporting/server/routes/generate_from_savedobject_immediate.ts b/x-pack/legacy/plugins/reporting/server/routes/generate_from_savedobject_immediate.ts index fec13019e58f3..2b2e8f618db63 100644 --- a/x-pack/legacy/plugins/reporting/server/routes/generate_from_savedobject_immediate.ts +++ b/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