From c22968f6f01fda67a02d0018ab0b63fafb427fa9 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Mon, 18 Apr 2022 07:08:43 -0700 Subject: [PATCH 01/28] use an EventLogger throughout a screenshotting flow --- x-pack/plugins/screenshotting/common/index.ts | 2 + .../server/formats/pdf/index.ts | 14 +- .../server/formats/pdf/pdf_maker/index.ts | 27 +- .../server/formats/pdf/pdf_maker/tracker.ts | 52 -- .../plugins/screenshotting/server/plugin.ts | 10 +- .../server/screenshots/event_logger/index.ts | 560 ++++++++++++++++++ .../get_element_position_data.test.ts | 11 +- .../screenshots/get_element_position_data.ts | 11 +- .../screenshots/get_number_of_items.test.ts | 14 +- .../server/screenshots/get_number_of_items.ts | 13 +- .../screenshots/get_render_errors.test.ts | 12 +- .../server/screenshots/get_render_errors.ts | 9 +- .../screenshots/get_screenshots.test.ts | 14 +- .../server/screenshots/get_screenshots.ts | 9 +- .../server/screenshots/get_time_range.test.ts | 14 +- .../server/screenshots/get_time_range.ts | 13 +- .../server/screenshots/index.ts | 44 +- .../server/screenshots/inject_css.ts | 14 +- .../server/screenshots/observable.test.ts | 11 +- .../server/screenshots/observable.ts | 32 +- .../server/screenshots/open_url.ts | 16 +- .../index.test.ts} | 2 +- .../{semaphore.ts => semaphore/index.ts} | 0 .../server/screenshots/wait_for_render.ts | 91 ++- .../screenshots/wait_for_visualizations.ts | 11 +- 25 files changed, 736 insertions(+), 270 deletions(-) delete mode 100644 x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/tracker.ts create mode 100644 x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts rename x-pack/plugins/screenshotting/server/screenshots/{semaphore.test.ts => semaphore/index.test.ts} (98%) rename x-pack/plugins/screenshotting/server/screenshots/{semaphore.ts => semaphore/index.ts} (100%) diff --git a/x-pack/plugins/screenshotting/common/index.ts b/x-pack/plugins/screenshotting/common/index.ts index b6b9034cb8189..7570477a1c1c9 100644 --- a/x-pack/plugins/screenshotting/common/index.ts +++ b/x-pack/plugins/screenshotting/common/index.ts @@ -14,3 +14,5 @@ export { SCREENSHOTTING_EXPRESSION, SCREENSHOTTING_EXPRESSION_INPUT, } from './expression'; + +export const PLUGIN_ID = 'screenshotting'; diff --git a/x-pack/plugins/screenshotting/server/formats/pdf/index.ts b/x-pack/plugins/screenshotting/server/formats/pdf/index.ts index 7a2453b2a426b..0219f4472751a 100644 --- a/x-pack/plugins/screenshotting/server/formats/pdf/index.ts +++ b/x-pack/plugins/screenshotting/server/formats/pdf/index.ts @@ -5,13 +5,14 @@ * 2.0. */ -import { groupBy } from 'lodash'; import type { Values } from '@kbn/utility-types'; -import type { Logger, PackageInfo } from '@kbn/core/server'; +import { groupBy } from 'lodash'; +import type { PackageInfo } from '@kbn/core/server'; import type { LayoutParams } from '../../../common'; import { LayoutTypes } from '../../../common'; import type { Layout } from '../../layouts'; -import type { CaptureOptions, CaptureResult, CaptureMetrics } from '../../screenshots'; +import type { CaptureMetrics, CaptureOptions, CaptureResult } from '../../screenshots'; +import { Actions, EventLogger } from '../../screenshots/event_logger'; import { pngsToPdf } from './pdf_maker'; /** @@ -92,7 +93,7 @@ function getTimeRange(results: CaptureResult['results']) { } export async function toPdf( - logger: Logger, + eventLogger: EventLogger, packageInfo: PackageInfo, layout: Layout, { logo, title }: PdfScreenshotOptions, @@ -106,7 +107,7 @@ export async function toPdf( layout, logo, packageInfo, - logger, + eventLogger, }); return { @@ -119,7 +120,8 @@ export async function toPdf( renderErrors: results.flatMap(({ renderErrors }) => renderErrors ?? []), }; } catch (error) { - logger.error(`Could not generate the PDF buffer!`); + eventLogger.kbnLogger.error(`Could not generate the PDF buffer!`); + eventLogger.error(error, Actions.PDF); throw error; } diff --git a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts index be69ec4c5e141..5c7b83b4cc5f2 100644 --- a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts +++ b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts @@ -5,17 +5,17 @@ * 2.0. */ -import type { Logger, PackageInfo } from '@kbn/core/server'; -import { PdfMaker } from './pdfmaker'; +import type { PackageInfo } from '@kbn/core/server'; import type { Layout } from '../../../layouts'; -import { getTracker } from './tracker'; import type { CaptureResult } from '../../../screenshots'; +import { EventLogger } from '../../../screenshots/event_logger'; +import { PdfMaker } from './pdfmaker'; interface PngsToPdfArgs { results: CaptureResult['results']; layout: Layout; packageInfo: PackageInfo; - logger: Logger; + eventLogger: EventLogger; logo?: string; title?: string; } @@ -26,37 +26,34 @@ export async function pngsToPdf({ logo, title, packageInfo, - logger, + eventLogger, }: PngsToPdfArgs): Promise<{ buffer: Buffer; pages: number }> { - const pdfMaker = new PdfMaker(layout, logo, packageInfo, logger); - const tracker = getTracker(); + eventLogger.pdfBegin(); + const pdfMaker = new PdfMaker(layout, logo, packageInfo, eventLogger.kbnLogger); if (title) { pdfMaker.setTitle(title); } results.forEach((result) => { result.screenshots.forEach((png) => { - tracker.startAddImage(); + eventLogger.addPdfImageBegin(); pdfMaker.addImage(png.data, { title: png.title ?? undefined, description: png.description ?? undefined, }); - tracker.endAddImage(); + eventLogger.addPdfImageEnd(); }); }); let buffer: Uint8Array | null = null; try { - tracker.startCompile(); + eventLogger.compilePdfBegin(); buffer = await pdfMaker.generate(); - tracker.endCompile(); + eventLogger.compilePdfEnd(); const byteLength = buffer?.byteLength ?? 0; - logger.debug(`PDF buffer byte length: ${byteLength}`); - tracker.setByteLength(byteLength); + eventLogger.pdfEnd({ byteLengthPdf: byteLength, pdfPages: pdfMaker.getPageCount() }); } catch (err) { throw err; - } finally { - tracker.end(); } return { buffer: Buffer.from(buffer.buffer), pages: pdfMaker.getPageCount() }; diff --git a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/tracker.ts b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/tracker.ts deleted file mode 100644 index 49576a03d18a3..0000000000000 --- a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/tracker.ts +++ /dev/null @@ -1,52 +0,0 @@ -/* - * 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; you may not use this file except in compliance with the Elastic License - * 2.0. - */ - -import apm from 'elastic-apm-node'; - -interface PdfTracker { - setByteLength: (byteLength: number) => void; - startAddImage: () => void; - endAddImage: () => void; - startCompile: () => void; - endCompile: () => void; - end: () => void; -} - -const TRANSACTION_TYPE = 'reporting'; // TODO: Find out whether we can rename to "screenshotting"; -const SPANTYPE_OUTPUT = 'output'; - -interface ApmSpan { - end: () => void; -} - -export function getTracker(): PdfTracker { - const apmTrans = apm.startTransaction('generate-pdf', TRANSACTION_TYPE); - - let apmAddImage: ApmSpan | null = null; - let apmCompilePdf: ApmSpan | null = null; - - return { - startAddImage() { - apmAddImage = apmTrans?.startSpan('add-pdf-image', SPANTYPE_OUTPUT) || null; - }, - endAddImage() { - apmAddImage?.end(); - }, - startCompile() { - apmCompilePdf = apmTrans?.startSpan('compile-pdf', SPANTYPE_OUTPUT) || null; - }, - endCompile() { - apmCompilePdf?.end(); - }, - setByteLength(byteLength: number) { - apmTrans?.setLabel('byte-length', byteLength, false); - }, - end() { - apmTrans?.end(); - }, - }; -} diff --git a/x-pack/plugins/screenshotting/server/plugin.ts b/x-pack/plugins/screenshotting/server/plugin.ts index 23f688206d394..11b26ef2831a7 100755 --- a/x-pack/plugins/screenshotting/server/plugin.ts +++ b/x-pack/plugins/screenshotting/server/plugin.ts @@ -83,9 +83,13 @@ export class ScreenshottingPlugin implements Plugin { const browserDriverFactory = await this.browserDriverFactory; - const logger = this.logger.get('screenshot'); - - return new Screenshots(browserDriverFactory, logger, this.packageInfo, http, this.config); + return new Screenshots( + browserDriverFactory, + this.logger, + this.packageInfo, + http, + this.config + ); })(); // Already handled in `browserDriverFactory` this.screenshots.catch(() => {}); diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts new file mode 100644 index 0000000000000..f5eb66499e305 --- /dev/null +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -0,0 +1,560 @@ +/* + * 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; you may not use this file except in compliance with the Elastic License + * 2.0. + */ + +import apm from 'elastic-apm-node'; +import { Logger, LogMeta } from '@kbn/core/server'; +import { CaptureResult } from '..'; +import { PLUGIN_ID } from '../../../common'; +import { Screenshot } from '../get_screenshots'; + +export enum Actions { + SCREENSHOTTING = 'screenshot-pipeline', + PDF = 'generate-pdf', + CREATE_LAYOUT = 'create-layout', + CREATE_PAGE = 'create-page', + GET_ELEMENT_POSITION_DATA = 'get-element-position-data', + GET_NUMBER_OF_ITEMS = 'get-number-of-items', + GET_RENDER_ERRORS = 'get-render-errors', + GET_SCREENSHOTS = 'get-screenshots', + GET_TIMERANGE = 'get-timerange', + INJECT_CSS = 'inject-css', + OPEN_URL = 'open-url', + REPOSITION = 'position-elements', + WAIT_RENDER = 'wait-for-render', + WAIT_VISUALIZATIONS = 'wait-for-visualizations', + ADD_IMAGE = 'add-pdf-image', + COMPILE = 'compile-pdf', +} + +enum SpanTypes { + SETUP = 'setup', + READ = 'read', + WAIT = 'wait', + CORRECT = 'correction', + OUTPUT = 'output', +} + +export interface ScreenshottingAction extends LogMeta { + event?: { + duration?: number; // number of nanoseconds from begin to end of an event + }; + + message: string; + kibana: { + screenshotting: { + action: Actions; + // flow_id: string; // TODO random uuid to trace a pipeline flow + // is_pdf: boolean; // TODO + cpu?: number; + cpu_percentage?: number; + memory?: number; + memory_mb?: number; + items_count?: number; + byte_length?: number; + byte_length_pdf?: number; + pdf_pages?: number; + render_errors?: number; + }; + }; +} + +interface ErrorAction { + message: string; + code?: string; + stack_trace?: string; + type?: string; +} + +interface PdfEndOptions { + byteLengthPdf: number; + pdfPages: number; +} + +interface RenderErrorsOptions { + renderErrors: number; +} + +interface NumberOfItemsOptions { + itemsCount: number; +} + +type SpanEntity = + | 'addPdfImage' + | 'compilePdf' + | 'createLayout' + | 'createPage' + | 'getElementPositionData' + | 'getNumberOfItems' + | 'getRenderErrors' + | 'getScreenshots' + | 'getTimeRange' + | 'injectCss' + | 'openUrl' + | 'positionElements' + | 'waitForRender' + | 'waitForVisualization'; + +type TransactionEntity = 'generatePdf' | 'screenshotting'; + +type LogAdapter = ( + message: string, + event: ScreenshottingAction['kibana']['screenshotting'], + startTime?: Date | undefined +) => void; + +function logAdapter(logger: Logger) { + const log: LogAdapter = ( + message: string, + event: ScreenshottingAction['kibana']['screenshotting'], + startTime?: Date | undefined + ) => { + let duration: number | undefined; + if (startTime != null) { + const start = startTime.valueOf(); + duration = new Date(Date.now()).valueOf() - start.valueOf(); + } + + logger.debug(message, { + message, + kibana: { screenshotting: event }, + event: { duration, provider: PLUGIN_ID }, + }); + }; + return log; +} + +/** + * A class to use internal state properties to log timing between actions in the screenshotting pipeline + */ +export class EventLogger { + private spans: Record = { + addPdfImage: null, + compilePdf: null, + createLayout: null, + createPage: null, + getElementPositionData: null, + getNumberOfItems: null, + getRenderErrors: null, + getScreenshots: null, + getTimeRange: null, + injectCss: null, + openUrl: null, + positionElements: null, + waitForRender: null, + waitForVisualization: null, + }; + + private transactions: Record = { + screenshotting: null, + generatePdf: null, + }; + + private logEventData: ReturnType; + private timings: Partial> = {}; + + constructor(private readonly logger: Logger) { + this.logEventData = logAdapter(logger.get('events')); + // TODO flow_id + } + + private startTiming(a: Actions) { + this.timings[a] = new Date(Date.now()); + } + + private sumScreenshotsByteLength = (byteLength: number, screenshot: Screenshot) => + byteLength + screenshot.data.byteLength; + + /** + * Helper to return the original logger + * + * @returns Logger + */ + public get kbnLogger() { + return this.logger; + } + + // Methods for transactions + + /** + * Signal when the screenshotting pipeline begins + * + * @returns void + */ + public screenshottingBegin() { + this.transactions.screenshotting = apm.startTransaction(Actions.SCREENSHOTTING, PLUGIN_ID); + this.logEventData( + 'screenshot-pipeline starting', + { action: Actions.SCREENSHOTTING } // + ); + this.startTiming(Actions.SCREENSHOTTING); + } + + /** + * Signal when the screenshotting pipeline finishes + * + * @param {CaptureResult} [TODO:name] - [TODO:description] + * @returns void + */ + public screenshottingEnd({ metrics, results }: CaptureResult) { + const cpu = metrics?.cpu; + const memory = metrics?.memory; + const byteLength = results.reduce( + (totals, { screenshots }) => totals + screenshots.reduce(this.sumScreenshotsByteLength, 0), + 0 + ); + + this.transactions.screenshotting?.setLabel('cpu', cpu, false); + this.transactions.screenshotting?.setLabel('memory', memory, false); + this.transactions.screenshotting?.setLabel('byte-length', byteLength, false); + this.transactions.screenshotting?.end(); + + this.logEventData( + 'screenshot-pipeline finished', + { action: Actions.SCREENSHOTTING, byte_length: byteLength, cpu, memory }, + this.timings[Actions.SCREENSHOTTING] + ); + } + + /** + * Signal when PdfMaker generation starts + * + * @returns void + */ + public pdfBegin() { + this.transactions.generatePdf = apm.startTransaction(Actions.PDF, PLUGIN_ID); + this.logEventData( + 'pdf generation starting', + { action: Actions.PDF } // + ); + this.startTiming(Actions.PDF); + } + + /** + * Signal when PdfMaker generation finishes + * + * @returns void + */ + public pdfEnd({ byteLengthPdf, pdfPages }: PdfEndOptions) { + this.transactions.generatePdf?.setLabel('byte-length', byteLengthPdf, false); + this.transactions.generatePdf?.setLabel('pdf-pages', pdfPages, false); + this.transactions.generatePdf?.end(); + + this.logEventData( + 'pdf generation finished', + { + action: Actions.PDF, + byte_length_pdf: byteLengthPdf, + pdf_pages: pdfPages, + }, + this.timings[Actions.PDF] + ); + } + + // Methods for spans + + public createLayoutBegin() { + this.spans.createLayout = this.transactions.screenshotting?.startSpan( + Actions.CREATE_LAYOUT, + SpanTypes.SETUP + ); + this.logEventData( + 'create-layout starting', + { action: Actions.CREATE_LAYOUT } // + ); + this.startTiming(Actions.CREATE_LAYOUT); + } + + public createLayoutEnd() { + this.spans.createLayout?.end(); + this.logEventData( + 'create-layout finished', + { action: Actions.CREATE_LAYOUT }, + this.timings[Actions.CREATE_LAYOUT] + ); + } + + public getElementPositionDataBegin() { + this.spans.getElementPositionData = this.transactions.screenshotting?.startSpan( + Actions.GET_ELEMENT_POSITION_DATA, + SpanTypes.READ + ); + this.logEventData( + 'getting element position data', + { action: Actions.GET_ELEMENT_POSITION_DATA } // + ); + this.startTiming(Actions.GET_ELEMENT_POSITION_DATA); + } + + public getElementPositionDataEnd() { + this.spans.getElementPositionData?.end(); + this.logEventData( + 'element position data read', + { action: Actions.GET_ELEMENT_POSITION_DATA }, + this.timings[Actions.GET_ELEMENT_POSITION_DATA] + ); + } + + public getNumberOfItemsBegin() { + this.spans.getNumberOfItems = this.transactions.screenshotting?.startSpan( + Actions.GET_NUMBER_OF_ITEMS, + SpanTypes.READ + ); + this.logEventData( + 'getting number of visualization items', + { action: Actions.GET_NUMBER_OF_ITEMS } // + ); + this.startTiming(Actions.GET_NUMBER_OF_ITEMS); + } + + public getNumberOfItemsEnd({ itemsCount }: NumberOfItemsOptions) { + this.spans.getNumberOfItems?.end(); + this.logEventData( + 'received number of visualization items', + { + action: Actions.GET_NUMBER_OF_ITEMS, + items_count: itemsCount, + }, + this.timings[Actions.GET_NUMBER_OF_ITEMS] + ); + } + + public getRenderErrorsBegin() { + this.spans.getRenderErrors = this.transactions.screenshotting?.startSpan( + Actions.GET_RENDER_ERRORS, + SpanTypes.READ + ); + this.logEventData( + 'starting scan for rendering errors', + { action: Actions.GET_RENDER_ERRORS } // + ); + this.startTiming(Actions.GET_RENDER_ERRORS); + } + + public getRenderErrorsEnd({ renderErrors }: RenderErrorsOptions) { + this.spans.getRenderErrors?.end(); + this.logEventData( + 'finished scanning for rendering errors', + { + action: Actions.GET_RENDER_ERRORS, + render_errors: renderErrors, + }, + this.timings[Actions.GET_RENDER_ERRORS] + ); + } + + public getScreenshotsBegin() { + this.spans.getScreenshots = this.transactions.screenshotting?.startSpan( + Actions.GET_SCREENSHOTS, + SpanTypes.READ + ); + this.logEventData( + 'capturing screenshots', + { action: Actions.GET_SCREENSHOTS } // + ); + this.startTiming(Actions.GET_SCREENSHOTS); + } + + public getScreenshotsEnd() { + this.spans.getScreenshots?.end(); + this.logEventData( + 'screenshots captured', + { action: Actions.GET_SCREENSHOTS }, + this.timings[Actions.GET_SCREENSHOTS] + ); + } + + public getTimeRangeBegin() { + this.spans.getTimeRange = this.transactions.screenshotting?.startSpan( + Actions.GET_TIMERANGE, + SpanTypes.READ + ); + this.logEventData( + 'getting time range', + { action: Actions.GET_TIMERANGE } // + ); + this.startTiming(Actions.GET_TIMERANGE); + } + + public getTimeRangeEnd() { + this.spans.getTimeRange?.end(); + this.logEventData( + 'received time range', + { action: Actions.GET_TIMERANGE }, + this.timings[Actions.GET_TIMERANGE] + ); + } + + public injectCssBegin() { + this.spans.injectCss = this.transactions.screenshotting?.startSpan( + Actions.INJECT_CSS, + SpanTypes.CORRECT + ); + this.logEventData( + 'injecting css', + { action: Actions.INJECT_CSS } // + ); + this.startTiming(Actions.INJECT_CSS); + } + + public injectCssEnd() { + this.spans.injectCss?.end(); + this.logEventData( + 'finished injecting css', + { action: Actions.INJECT_CSS }, + this.timings[Actions.INJECT_CSS] + ); + } + + public openUrlBegin() { + this.spans.openUrl = this.transactions.screenshotting?.startSpan( + Actions.OPEN_URL, + SpanTypes.WAIT + ); + this.logEventData( + 'opening url', + { action: Actions.OPEN_URL } // + ); + this.startTiming(Actions.OPEN_URL); + } + + public openUrlEnd() { + this.spans.openUrl?.end(); + this.logEventData( + 'finished opening url', + { action: Actions.OPEN_URL }, + this.timings[Actions.OPEN_URL] + ); + } + + public positionElementsBegin() { + this.spans.positionElements = this.transactions.screenshotting?.startSpan( + Actions.REPOSITION, + SpanTypes.CORRECT + ); + this.logEventData( + 'positioning elements', + { action: Actions.REPOSITION } // + ); + this.startTiming(Actions.REPOSITION); + } + + public positionElementsEnd() { + this.spans.positionElements?.end(); + this.logEventData( + 'finished positioning elements', + { action: Actions.REPOSITION }, + this.timings[Actions.REPOSITION] + ); + } + + public waitForRenderBegin() { + this.spans.waitForRender = this.transactions.screenshotting?.startSpan( + Actions.WAIT_RENDER, + SpanTypes.WAIT + ); + this.logEventData( + 'waiting for render to complete', + { action: Actions.WAIT_RENDER } // + ); + this.startTiming(Actions.WAIT_RENDER); + } + + public waitForRenderEnd() { + this.spans.waitForRender?.end(); + this.logEventData( + 'finished waiting for render to complete', + { action: Actions.WAIT_RENDER }, + this.timings[Actions.WAIT_RENDER] + ); + } + + public waitForVisualizationBegin() { + this.spans.waitForVisualization = this.transactions.screenshotting?.startSpan( + Actions.WAIT_VISUALIZATIONS, + SpanTypes.WAIT + ); + this.logEventData( + 'waiting for visualizations', + { action: Actions.WAIT_VISUALIZATIONS } // + ); + this.startTiming(Actions.WAIT_VISUALIZATIONS); + } + + public waitForVisualizationEnd() { + this.spans.waitForVisualization?.end(); + this.logEventData( + 'finished waiting for visualizations', + { action: Actions.WAIT_VISUALIZATIONS }, + this.timings[Actions.WAIT_VISUALIZATIONS] + ); + } + + public addPdfImageBegin() { + this.spans.addPdfImage = this.transactions.generatePdf?.startSpan( + Actions.ADD_IMAGE, + SpanTypes.OUTPUT + ); + this.logEventData( + 'adding pdf image', + { action: Actions.ADD_IMAGE } // + ); + this.startTiming(Actions.ADD_IMAGE); + } + + public addPdfImageEnd() { + this.spans.addPdfImage?.end(); + this.logEventData( + 'pdf image added', + { action: Actions.ADD_IMAGE }, + this.timings[Actions.ADD_IMAGE] + ); + } + + public compilePdfBegin() { + this.spans.compilePdf = this.transactions.generatePdf?.startSpan( + Actions.COMPILE, + SpanTypes.OUTPUT + ); + this.logEventData( + 'compiling pdf file', + { action: Actions.COMPILE } // + ); + this.startTiming(Actions.COMPILE); + } + + public compilePdfEnd() { + this.spans.compilePdf?.end(); + this.logEventData( + 'pdf file compiled', + { action: Actions.COMPILE }, + this.timings[Actions.COMPILE] + ); + } + + /** + * General error logger + * + * @param {ErrorAction} error: The error object that was caught + * @param {Actions} action: The screenshotting action type + * @returns void + */ + public error(error: ErrorAction | string, action: Actions) { + const isError = typeof error === 'object'; + this.logger.error(error as Error); + this.logger.debug('an error occurred', { + message: 'an error occurred', + kibana: { screenshotting: { action } }, + event: { provider: PLUGIN_ID }, + error: { + message: isError ? error.message : undefined, + code: isError ? error.code : undefined, + stack_trace: isError ? error.stack_trace : undefined, + type: isError ? error.type : undefined, + }, + }); + } +} diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts index 915b036acf22e..6b3db8628cffb 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts @@ -5,20 +5,21 @@ * 2.0. */ -import type { Logger } from '@kbn/core/server'; +import { loggingSystemMock } from '@kbn/core/server/mocks'; import { createMockBrowserDriver } from '../browsers/mock'; import { createMockLayout } from '../layouts/mock'; +import { EventLogger } from './event_logger'; import { getElementPositionAndAttributes } from './get_element_position_data'; describe('getElementPositionAndAttributes', () => { - const logger = {} as jest.Mocked; let browser: ReturnType; let layout: ReturnType; + let eventLogger: EventLogger; beforeEach(async () => { browser = createMockBrowserDriver(); layout = createMockLayout(); - + eventLogger = new EventLogger(loggingSystemMock.createLogger()); browser.evaluate.mockImplementation(({ fn, args }) => (fn as Function)(...args)); // @see https://github.com/jsdom/jsdom/issues/653 @@ -59,7 +60,7 @@ describe('getElementPositionAndAttributes', () => { /> `; - await expect(getElementPositionAndAttributes(browser, logger, layout)).resolves + await expect(getElementPositionAndAttributes(browser, eventLogger, layout)).resolves .toMatchInlineSnapshot(` Array [ Object { @@ -103,6 +104,6 @@ describe('getElementPositionAndAttributes', () => { }); it('should return null when there are no elements matching', async () => { - await expect(getElementPositionAndAttributes(browser, logger, layout)).resolves.toBeNull(); + await expect(getElementPositionAndAttributes(browser, eventLogger, layout)).resolves.toBeNull(); }); }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index e3235c6d23253..9c8f2460e9434 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -5,11 +5,10 @@ * 2.0. */ -import apm from 'elastic-apm-node'; -import type { Logger } from '@kbn/core/server'; import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_ELEMENTATTRIBUTES } from './constants'; +import { Actions, EventLogger } from './event_logger'; export interface AttributesMap { [key: string]: string | null; @@ -36,10 +35,9 @@ export interface ElementsPositionAndAttribute { export const getElementPositionAndAttributes = async ( browser: HeadlessChromiumDriver, - logger: Logger, + eventLogger: EventLogger, layout: Layout ): Promise => { - const span = apm.startSpan('get_element_position_data', 'read'); const { screenshot: screenshotSelector } = layout.selectors; // data-shared-items-container let elementsPositionAndAttributes: ElementsPositionAndAttribute[] | null; try { @@ -77,7 +75,7 @@ export const getElementPositionAndAttributes = async ( args: [screenshotSelector, { title: 'data-title', description: 'data-description' }], }, { context: CONTEXT_ELEMENTATTRIBUTES }, - logger + eventLogger.kbnLogger ); if (!elementsPositionAndAttributes?.length) { @@ -86,10 +84,9 @@ export const getElementPositionAndAttributes = async ( ); } } catch (err) { + eventLogger.error(err, Actions.GET_ELEMENT_POSITION_DATA); elementsPositionAndAttributes = null; } - span?.end(); - return elementsPositionAndAttributes; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.test.ts index 34b8291eb03da..5aa0a75ab206e 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.test.ts @@ -5,22 +5,22 @@ * 2.0. */ -import type { Logger } from '@kbn/core/server'; +import { loggingSystemMock } from '@kbn/core/server/mocks'; import { createMockBrowserDriver } from '../browsers/mock'; import { createMockLayout } from '../layouts/mock'; +import { EventLogger } from './event_logger'; import { getNumberOfItems } from './get_number_of_items'; describe('getNumberOfItems', () => { const timeout = 10; let browser: ReturnType; let layout: ReturnType; - let logger: jest.Mocked; + let eventLogger: EventLogger; beforeEach(async () => { browser = createMockBrowserDriver(); layout = createMockLayout(); - logger = { debug: jest.fn() } as unknown as jest.Mocked; - + eventLogger = new EventLogger(loggingSystemMock.createLogger()); browser.evaluate.mockImplementation(({ fn, args }) => (fn as Function)(...args)); }); @@ -33,7 +33,7 @@ describe('getNumberOfItems', () => {
`; - await expect(getNumberOfItems(browser, logger, timeout, layout)).resolves.toBe(10); + await expect(getNumberOfItems(browser, eventLogger, timeout, layout)).resolves.toBe(10); }); it('should determine the number of items by selector ', async () => { @@ -43,7 +43,7 @@ describe('getNumberOfItems', () => { `; - await expect(getNumberOfItems(browser, logger, timeout, layout)).resolves.toBe(3); + await expect(getNumberOfItems(browser, eventLogger, timeout, layout)).resolves.toBe(3); }); it('should fall back to the selector when the attribute is empty', async () => { @@ -53,6 +53,6 @@ describe('getNumberOfItems', () => { `; - await expect(getNumberOfItems(browser, logger, timeout, layout)).resolves.toBe(2); + await expect(getNumberOfItems(browser, eventLogger, timeout, layout)).resolves.toBe(2); }); }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts index 9dab001e4730d..0798d3a519c70 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts @@ -5,24 +5,21 @@ * 2.0. */ -import apm from 'elastic-apm-node'; -import type { Logger } from '@kbn/core/server'; import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_GETNUMBEROFITEMS, CONTEXT_READMETADATA } from './constants'; +import { Actions, EventLogger } from './event_logger'; export const getNumberOfItems = async ( browser: HeadlessChromiumDriver, - logger: Logger, + eventLogger: EventLogger, timeout: number, layout: Layout ): Promise => { - const span = apm.startSpan('get_number_of_items', 'read'); + const logger = eventLogger.kbnLogger; const { renderComplete: renderCompleteSelector, itemsCountAttribute } = layout.selectors; let itemsCount: number; - logger.debug('waiting for elements or items count attribute; or not found to interrupt'); - try { // the dashboard is using the `itemsCountAttribute` attribute to let us // know how many items to expect since gridster incrementally adds panels @@ -55,13 +52,11 @@ export const getNumberOfItems = async ( logger ); } catch (error) { - logger.error(error); + eventLogger.error(error, Actions.GET_NUMBER_OF_ITEMS); throw new Error( `An error occurred when trying to read the page for visualization panel info: ${error.message}` ); } - span?.end(); - return itemsCount; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.test.ts index a475e3c614c15..e2ffa8faf6e9f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.test.ts @@ -5,21 +5,21 @@ * 2.0. */ -import type { Logger } from '@kbn/core/server'; +import { loggingSystemMock } from '@kbn/core/server/mocks'; import { createMockBrowserDriver } from '../browsers/mock'; import { createMockLayout } from '../layouts/mock'; +import { EventLogger } from './event_logger'; import { getRenderErrors } from './get_render_errors'; describe('getRenderErrors', () => { let browser: ReturnType; let layout: ReturnType; - let logger: jest.Mocked; + let eventLogger: EventLogger; beforeEach(async () => { browser = createMockBrowserDriver(); layout = createMockLayout(); - logger = { debug: jest.fn(), warn: jest.fn() } as unknown as jest.Mocked; - + eventLogger = new EventLogger(loggingSystemMock.createLogger()); browser.evaluate.mockImplementation(({ fn, args }) => (fn as Function)(...args)); }); @@ -35,7 +35,7 @@ describe('getRenderErrors', () => {
`; - await expect(getRenderErrors(browser, logger, layout)).resolves.toEqual([ + await expect(getRenderErrors(browser, eventLogger, layout)).resolves.toEqual([ 'a test error', 'a test error', 'a test error', @@ -48,6 +48,6 @@ describe('getRenderErrors', () => { `; - await expect(getRenderErrors(browser, logger, layout)).resolves.toEqual(undefined); + await expect(getRenderErrors(browser, eventLogger, layout)).resolves.toEqual(undefined); }); }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts index e8beb18911210..6b36b28fe1383 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts @@ -5,19 +5,17 @@ * 2.0. */ -import apm from 'elastic-apm-node'; -import type { Logger } from '@kbn/core/server'; import type { HeadlessChromiumDriver } from '../browsers'; import type { Layout } from '../layouts'; import { CONTEXT_GETRENDERERRORS } from './constants'; +import { EventLogger } from './event_logger'; export const getRenderErrors = async ( browser: HeadlessChromiumDriver, - logger: Logger, + eventLogger: EventLogger, layout: Layout ): Promise => { - const span = apm.startSpan('get_render_errors', 'read'); - logger.debug('reading render errors'); + const { kbnLogger: logger } = eventLogger; const errorsFound: undefined | string[] = await browser.evaluate( { fn: (errorSelector, errorAttribute) => { @@ -38,7 +36,6 @@ export const getRenderErrors = async ( { context: CONTEXT_GETRENDERERRORS }, logger ); - span?.end(); if (errorsFound?.length) { logger.warn( diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts index 1f104b9bf2d80..8313d7116ee71 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts @@ -5,8 +5,9 @@ * 2.0. */ -import type { Logger } from '@kbn/core/server'; +import { loggingSystemMock } from '@kbn/core/server/mocks'; import { createMockBrowserDriver } from '../browsers/mock'; +import { EventLogger } from './event_logger'; import { getScreenshots } from './get_screenshots'; describe('getScreenshots', () => { @@ -27,12 +28,11 @@ describe('getScreenshots', () => { }, ]; let browser: ReturnType; - let logger: jest.Mocked; + let eventLogger: EventLogger; beforeEach(async () => { browser = createMockBrowserDriver(); - logger = { info: jest.fn() } as unknown as jest.Mocked; - + eventLogger = new EventLogger(loggingSystemMock.createLogger()); browser.evaluate.mockImplementation(({ fn, args }) => (fn as Function)(...args)); }); @@ -41,7 +41,7 @@ describe('getScreenshots', () => { }); it('should return screenshots', async () => { - await expect(getScreenshots(browser, logger, elementsPositionAndAttributes)).resolves + await expect(getScreenshots(browser, eventLogger, elementsPositionAndAttributes)).resolves .toMatchInlineSnapshot(` Array [ Object { @@ -87,7 +87,7 @@ describe('getScreenshots', () => { }); it('should forward elements positions', async () => { - await getScreenshots(browser, logger, elementsPositionAndAttributes); + await getScreenshots(browser, eventLogger, elementsPositionAndAttributes); expect(browser.screenshot).toHaveBeenCalledTimes(2); expect(browser.screenshot).toHaveBeenNthCalledWith( @@ -104,7 +104,7 @@ describe('getScreenshots', () => { browser.screenshot.mockResolvedValue(Buffer.from('')); await expect( - getScreenshots(browser, logger, elementsPositionAndAttributes) + getScreenshots(browser, eventLogger, elementsPositionAndAttributes) ).rejects.toBeInstanceOf(Error); }); }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index 53829b098ee8c..50b6776dd2722 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -5,9 +5,8 @@ * 2.0. */ -import apm from 'elastic-apm-node'; -import type { Logger } from '@kbn/core/server'; import type { HeadlessChromiumDriver } from '../browsers'; +import { EventLogger } from './event_logger'; import type { ElementsPositionAndAttribute } from './get_element_position_data'; export interface Screenshot { @@ -29,15 +28,15 @@ export interface Screenshot { export const getScreenshots = async ( browser: HeadlessChromiumDriver, - logger: Logger, + eventLogger: EventLogger, elementsPositionAndAttributes: ElementsPositionAndAttribute[] ): Promise => { + const { kbnLogger: logger } = eventLogger; logger.info(`taking screenshots`); const screenshots: Screenshot[] = []; for (let i = 0; i < elementsPositionAndAttributes.length; i++) { - const span = apm.startSpan('get_screenshots', 'read'); const item = elementsPositionAndAttributes[i]; const data = await browser.screenshot(item.position); @@ -51,8 +50,6 @@ export const getScreenshots = async ( title: item.attributes.title, description: item.attributes.description, }); - - span?.end(); } logger.info(`screenshots taken: ${screenshots.length}`); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.test.ts index 8484412f5fd94..ed647e093e67e 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.test.ts @@ -5,21 +5,21 @@ * 2.0. */ -import type { Logger } from '@kbn/core/server'; +import { loggingSystemMock } from '@kbn/core/server/mocks'; import { createMockBrowserDriver } from '../browsers/mock'; import { createMockLayout } from '../layouts/mock'; +import { EventLogger } from './event_logger'; import { getTimeRange } from './get_time_range'; describe('getTimeRange', () => { let browser: ReturnType; let layout: ReturnType; - let logger: jest.Mocked; + let eventLogger: EventLogger; beforeEach(async () => { browser = createMockBrowserDriver(); layout = createMockLayout(); - logger = { debug: jest.fn(), info: jest.fn() } as unknown as jest.Mocked; - + eventLogger = new EventLogger(loggingSystemMock.createLogger()); browser.evaluate.mockImplementation(({ fn, args }) => (fn as Function)(...args)); }); @@ -28,7 +28,7 @@ describe('getTimeRange', () => { }); it('should return null when there is no duration element', async () => { - await expect(getTimeRange(browser, logger, layout)).resolves.toBeNull(); + await expect(getTimeRange(browser, eventLogger, layout)).resolves.toBeNull(); }); it('should return null when duration attrbute is empty', async () => { @@ -36,7 +36,7 @@ describe('getTimeRange', () => {
`; - await expect(getTimeRange(browser, logger, layout)).resolves.toBeNull(); + await expect(getTimeRange(browser, eventLogger, layout)).resolves.toBeNull(); }); it('should return duration', async () => { @@ -44,6 +44,6 @@ describe('getTimeRange', () => {
`; - await expect(getTimeRange(browser, logger, layout)).resolves.toBe('10'); + await expect(getTimeRange(browser, eventLogger, layout)).resolves.toBe('10'); }); }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts index 41d902436d36b..9daff0f26d67c 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts @@ -5,20 +5,17 @@ * 2.0. */ -import apm from 'elastic-apm-node'; -import type { Logger } from '@kbn/core/server'; import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_GETTIMERANGE } from './constants'; +import { EventLogger } from './event_logger'; export const getTimeRange = async ( browser: HeadlessChromiumDriver, - logger: Logger, + eventLogger: EventLogger, layout: Layout ): Promise => { - const span = apm.startSpan('get_time_range', 'read'); - logger.debug('getting timeRange'); - + const logger = eventLogger.kbnLogger; const timeRange = await browser.evaluate( { fn: (durationAttribute) => { @@ -43,11 +40,7 @@ export const getTimeRange = async ( if (timeRange) { logger.info(`timeRange: ${timeRange}`); - } else { - logger.debug('no timeRange'); } - span?.end(); - return timeRange; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/index.ts b/x-pack/plugins/screenshotting/server/screenshots/index.ts index 3fa0f1d222c3d..5537ec94f1345 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/index.ts @@ -8,8 +8,6 @@ import type { HttpServiceSetup, KibanaRequest, Logger, PackageInfo } from '@kbn/core/server'; import type { ExpressionAstExpression } from '@kbn/expressions-plugin/common'; import type { Optional } from '@kbn/utility-types'; -import type { Transaction } from 'elastic-apm-node'; -import apm from 'elastic-apm-node'; import ipaddr from 'ipaddr.js'; import { defaultsDeep, sum } from 'lodash'; import { from, Observable, of } from 'rxjs'; @@ -43,6 +41,7 @@ import { } from '../formats'; import type { Layout } from '../layouts'; import { createLayout } from '../layouts'; +import { EventLogger } from './event_logger'; import type { ScreenshotObservableOptions, ScreenshotObservableResult } from './observable'; import { ScreenshotObservableHandler, UrlOrUrlWithContext } from './observable'; import { Semaphore } from './semaphore'; @@ -95,6 +94,7 @@ const DEFAULT_SETUP_RESULT = { export class Screenshots { private semaphore: Semaphore; + private eventLogger: EventLogger; constructor( private readonly browserDriverFactory: HeadlessChromiumDriverFactory, @@ -103,24 +103,23 @@ export class Screenshots { private readonly http: HttpServiceSetup, private readonly config: ConfigType ) { + this.eventLogger = new EventLogger(logger); this.semaphore = new Semaphore(config.poolSize); } - private createLayout(transaction: Transaction | null, options: CaptureOptions): Layout { - const apmCreateLayout = transaction?.startSpan('create-layout', 'setup'); + private createLayout(options: CaptureOptions): Layout { + this.eventLogger.createLayoutBegin(); const layout = createLayout(options.layout ?? {}); this.logger.debug(`Layout: width=${layout.width} height=${layout.height}`); - apmCreateLayout?.end(); + this.eventLogger.createLayoutEnd(); return layout; } private captureScreenshots( layout: Layout, - transaction: Transaction | null, options: ScreenshotObservableOptions ): Observable { - const apmCreatePage = transaction?.startSpan('create-page', 'wait'); const { browserTimezone } = options; return this.browserDriverFactory @@ -135,20 +134,17 @@ export class Screenshots { .pipe( this.semaphore.acquire(), mergeMap(({ driver, unexpectedExit$, close }) => { - apmCreatePage?.end(); - unexpectedExit$.subscribe({ error: () => transaction?.end() }); - const screen = new ScreenshotObservableHandler( driver, this.config, - this.logger, + this.eventLogger, layout, options ); return from(options.urls).pipe( concatMap((url, index) => - screen.setupPage(index, url, transaction).pipe( + screen.setupPage(index, url).pipe( catchError((error) => { screen.checkPageIsOpen(); // this fails the job if the browser has closed @@ -162,16 +158,8 @@ export class Screenshots { take(options.urls.length), toArray(), mergeMap((results) => - // At this point we no longer need the page, close it. - close().pipe( - tap(({ metrics }) => { - if (metrics) { - transaction?.setLabel('cpu', metrics.cpu, false); - transaction?.setLabel('memory', metrics.memory, false); - } - }), - map(({ metrics }) => ({ metrics, results })) - ) + // At this point we no longer need the page, close it and send out the results + close().pipe(map(({ metrics }) => ({ metrics, results }))) ) ); }), @@ -232,15 +220,19 @@ export class Screenshots { getScreenshots(options: PdfScreenshotOptions): Observable; getScreenshots(options: ScreenshotOptions): Observable; getScreenshots(options: ScreenshotOptions): Observable { - const transaction = apm.startTransaction('screenshot-pipeline', 'screenshotting'); - const layout = this.createLayout(transaction, options); + this.eventLogger.screenshottingBegin(); + + const layout = this.createLayout(options); const captureOptions = this.getCaptureOptions(options); - return this.captureScreenshots(layout, transaction, captureOptions).pipe( + return this.captureScreenshots(layout, captureOptions).pipe( + tap((results) => { + this.eventLogger.screenshottingEnd(results); + }), mergeMap((result) => { switch (options.format) { case 'pdf': - return toPdf(this.logger, this.packageInfo, layout, options, result); + return toPdf(this.eventLogger, this.packageInfo, layout, options, result); default: return toPng(result); } diff --git a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts index a77cfa8c9e8e6..cbcab3889d2a3 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts @@ -7,21 +7,19 @@ import fs from 'fs'; import { promisify } from 'util'; -import apm from 'elastic-apm-node'; -import type { Logger } from '@kbn/core/server'; import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_INJECTCSS } from './constants'; +import { Actions, EventLogger } from './event_logger'; const fsp = { readFile: promisify(fs.readFile) }; export const injectCustomCss = async ( browser: HeadlessChromiumDriver, - logger: Logger, + eventLogger: EventLogger, layout: Layout ): Promise => { - const span = apm.startSpan('inject_css', 'correction'); - logger.debug('injecting custom css'); + eventLogger.injectCssBegin(); const filePath = layout.getCssOverridesPath(); if (!filePath) { @@ -40,14 +38,14 @@ export const injectCustomCss = async ( args: [buffer.toString()], }, { context: CONTEXT_INJECTCSS }, - logger + eventLogger.kbnLogger ); } catch (err) { - logger.error(err); + eventLogger.error(err, Actions.INJECT_CSS); throw new Error( `An error occurred when trying to update Kibana CSS for reporting. ${err.message}` ); } - span?.end(); + eventLogger.injectCssEnd(); }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.test.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.test.ts index d3acc96411dc6..a67aff8334cce 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.test.ts @@ -5,19 +5,20 @@ * 2.0. */ +import { loggingSystemMock } from '@kbn/core/server/mocks'; import { interval, of, throwError } from 'rxjs'; import { map } from 'rxjs/operators'; -import type { Logger } from '@kbn/core/server'; import { createMockBrowserDriver } from '../browsers/mock'; import type { ConfigType } from '../config'; import { createMockLayout } from '../layouts/mock'; +import { EventLogger } from './event_logger'; import { ScreenshotObservableHandler, ScreenshotObservableOptions } from './observable'; describe('ScreenshotObservableHandler', () => { let browser: ReturnType; let config: ConfigType; let layout: ReturnType; - let logger: jest.Mocked; + let eventLogger: EventLogger; let options: ScreenshotObservableOptions; beforeEach(async () => { @@ -34,7 +35,7 @@ describe('ScreenshotObservableHandler', () => { }, } as ConfigType; layout = createMockLayout(); - logger = { error: jest.fn() } as unknown as jest.Mocked; + eventLogger = new EventLogger(loggingSystemMock.createLogger()); options = { headers: { testHeader: 'testHeadValue' }, urls: [], @@ -46,7 +47,7 @@ describe('ScreenshotObservableHandler', () => { describe('waitUntil', () => { let screenshots: ScreenshotObservableHandler; beforeEach(() => { - screenshots = new ScreenshotObservableHandler(browser, config, logger, layout, options); + screenshots = new ScreenshotObservableHandler(browser, config, eventLogger, layout, options); }); it('catches TimeoutError and references the timeout config in a custom message', async () => { @@ -79,7 +80,7 @@ describe('ScreenshotObservableHandler', () => { describe('checkPageIsOpen', () => { let screenshots: ScreenshotObservableHandler; beforeEach(() => { - screenshots = new ScreenshotObservableHandler(browser, config, logger, layout, options); + screenshots = new ScreenshotObservableHandler(browser, config, eventLogger, layout, options); }); it('throws a decorated Error when page is not open', async () => { diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index b19f3f254b2a2..2e2ef88119b4f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -5,15 +5,15 @@ * 2.0. */ -import type { Transaction } from 'elastic-apm-node'; +import type { Headers } from '@kbn/core/server'; import { defer, forkJoin, Observable, throwError } from 'rxjs'; import { catchError, mergeMap, switchMapTo, timeoutWith } from 'rxjs/operators'; -import type { Headers, Logger } from '@kbn/core/server'; import { errors } from '../../common'; import type { Context, HeadlessChromiumDriver } from '../browsers'; import { DEFAULT_VIEWPORT, getChromiumDisconnectedError } from '../browsers'; -import { durationToNumber as toNumber, ConfigType } from '../config'; +import { ConfigType, durationToNumber as toNumber } from '../config'; import type { Layout } from '../layouts'; +import { EventLogger } from './event_logger'; import type { ElementsPositionAndAttribute } from './get_element_position_data'; import { getElementPositionAndAttributes } from './get_element_position_data'; import { getNumberOfItems } from './get_number_of_items'; @@ -118,7 +118,7 @@ export class ScreenshotObservableHandler { constructor( private readonly driver: HeadlessChromiumDriver, private readonly config: ConfigType, - private readonly logger: Logger, + private readonly eventLogger: EventLogger, private readonly layout: Layout, private options: ScreenshotObservableOptions ) {} @@ -154,7 +154,7 @@ export class ScreenshotObservableHandler { return openUrl( this.driver, - this.logger, + this.eventLogger, toNumber(this.config.capture.timeouts.openUrl), index, url, @@ -168,34 +168,34 @@ export class ScreenshotObservableHandler { const driver = this.driver; const waitTimeout = toNumber(this.config.capture.timeouts.waitForElements); - return defer(() => getNumberOfItems(driver, this.logger, waitTimeout, this.layout)).pipe( + return defer(() => getNumberOfItems(driver, this.eventLogger, waitTimeout, this.layout)).pipe( mergeMap(async (itemsCount) => { // set the viewport to the dimensions from the job, to allow elements to flow into the expected layout const viewport = this.layout.getViewport(itemsCount) || getDefaultViewPort(); // Set the viewport allowing time for the browser to handle reflow and redraw // before checking for readiness of visualizations. - await driver.setViewport(viewport, this.logger); - await waitForVisualizations(driver, this.logger, waitTimeout, itemsCount, this.layout); + await driver.setViewport(viewport, this.eventLogger.kbnLogger); + await waitForVisualizations(driver, this.eventLogger, waitTimeout, itemsCount, this.layout); }), this.waitUntil(waitTimeout, 'wait for elements') ); } - private completeRender(apmTrans: Transaction | null) { + private completeRender() { const driver = this.driver; const layout = this.layout; - const logger = this.logger; + const logger = this.eventLogger; return defer(async () => { // Waiting till _after_ elements have rendered before injecting our CSS // allows for them to be displayed properly in many cases await injectCustomCss(driver, logger, layout); - const apmPositionElements = apmTrans?.startSpan('position-elements', 'correction'); + this.eventLogger.positionElementsBegin(); // position panel elements for print layout - await layout.positionElements?.(driver, logger); - apmPositionElements?.end(); + await layout.positionElements?.(driver, logger.kbnLogger); + this.eventLogger.positionElementsEnd(); await waitForRenderComplete(driver, logger, toNumber(this.config.capture.loadDelay), layout); }).pipe( @@ -210,10 +210,10 @@ export class ScreenshotObservableHandler { ); } - public setupPage(index: number, url: UrlOrUrlWithContext, apmTrans: Transaction | null) { + public setupPage(index: number, url: UrlOrUrlWithContext) { return this.openUrl(index, url).pipe( switchMapTo(this.waitForElements()), - switchMapTo(this.completeRender(apmTrans)) + switchMapTo(this.completeRender()) ); } @@ -227,7 +227,7 @@ export class ScreenshotObservableHandler { getDefaultElementPosition(this.layout.getViewport(1)); let screenshots: Screenshot[] = []; try { - screenshots = await getScreenshots(this.driver, this.logger, elements); + screenshots = await getScreenshots(this.driver, this.eventLogger, elements); } catch (e) { throw new errors.FailedToCaptureScreenshot(e.message); } diff --git a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts index c557374ff9876..3d55b8e770c0f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts @@ -5,15 +5,14 @@ * 2.0. */ -import apm from 'elastic-apm-node'; -import type { Headers, Logger } from '@kbn/core/server'; -import type { HeadlessChromiumDriver } from '../browsers'; -import type { Context } from '../browsers'; +import type { Headers } from '@kbn/core/server'; +import type { Context, HeadlessChromiumDriver } from '../browsers'; import { DEFAULT_PAGELOAD_SELECTOR } from './constants'; +import { Actions, EventLogger } from './event_logger'; export const openUrl = async ( browser: HeadlessChromiumDriver, - logger: Logger, + eventLogger: EventLogger, timeout: number, index: number, url: string, @@ -24,14 +23,11 @@ export const openUrl = async ( // it's loaded the next page. const page = index + 1; const waitForSelector = page > 1 ? `[data-shared-page="${page}"]` : DEFAULT_PAGELOAD_SELECTOR; - const span = apm.startSpan('open_url', 'wait'); try { - await browser.open(url, { context, headers, waitForSelector, timeout }, logger); + await browser.open(url, { context, headers, waitForSelector, timeout }, eventLogger.kbnLogger); } catch (err) { - logger.error(err); + eventLogger.error(err, Actions.OPEN_URL); throw new Error(`An error occurred when trying to open the Kibana URL: ${err.message}`); } - - span?.end(); }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/semaphore.test.ts b/x-pack/plugins/screenshotting/server/screenshots/semaphore/index.test.ts similarity index 98% rename from x-pack/plugins/screenshotting/server/screenshots/semaphore.test.ts rename to x-pack/plugins/screenshotting/server/screenshots/semaphore/index.test.ts index 6d6dd21347974..0cc40a83723a9 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/semaphore.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/semaphore/index.test.ts @@ -6,7 +6,7 @@ */ import { TestScheduler } from 'rxjs/testing'; -import { Semaphore } from './semaphore'; +import { Semaphore } from '.'; describe('Semaphore', () => { let testScheduler: TestScheduler; diff --git a/x-pack/plugins/screenshotting/server/screenshots/semaphore.ts b/x-pack/plugins/screenshotting/server/screenshots/semaphore/index.ts similarity index 100% rename from x-pack/plugins/screenshotting/server/screenshots/semaphore.ts rename to x-pack/plugins/screenshotting/server/screenshots/semaphore/index.ts diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts index cee23616faeac..8b4ea2ff1347f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts @@ -5,72 +5,61 @@ * 2.0. */ -import apm from 'elastic-apm-node'; -import type { Logger } from '@kbn/core/server'; import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_WAITFORRENDER } from './constants'; +import { EventLogger } from './event_logger'; export const waitForRenderComplete = async ( browser: HeadlessChromiumDriver, - logger: Logger, + eventLogger: EventLogger, loadDelay: number, layout: Layout ) => { - const span = apm.startSpan('wait_for_render', 'wait'); + return await browser.evaluate( + { + fn: (selector, visLoadDelay) => { + // wait for visualizations to finish loading + const visualizations: NodeListOf = document.querySelectorAll(selector); + const visCount = visualizations.length; + const renderedTasks = []; - logger.debug('waiting for rendering to complete'); + function waitForRender(visualization: Element) { + return new Promise((resolve) => { + visualization.addEventListener('renderComplete', () => resolve()); + }); + } - return await browser - .evaluate( - { - fn: (selector, visLoadDelay) => { - // wait for visualizations to finish loading - const visualizations: NodeListOf = document.querySelectorAll(selector); - const visCount = visualizations.length; - const renderedTasks = []; + function waitForRenderDelay() { + return new Promise((resolve) => { + setTimeout(resolve, visLoadDelay); + }); + } - function waitForRender(visualization: Element) { - return new Promise((resolve) => { - visualization.addEventListener('renderComplete', () => resolve()); - }); - } + for (let i = 0; i < visCount; i++) { + const visualization = visualizations[i]; + const isRendered = visualization.getAttribute('data-render-complete'); - function waitForRenderDelay() { - return new Promise((resolve) => { - setTimeout(resolve, visLoadDelay); - }); + if (isRendered === 'disabled') { + renderedTasks.push(waitForRenderDelay()); + } else if (isRendered === 'false') { + renderedTasks.push(waitForRender(visualization)); } + } - for (let i = 0; i < visCount; i++) { - const visualization = visualizations[i]; - const isRendered = visualization.getAttribute('data-render-complete'); - - if (isRendered === 'disabled') { - renderedTasks.push(waitForRenderDelay()); - } else if (isRendered === 'false') { - renderedTasks.push(waitForRender(visualization)); - } - } + // The renderComplete fires before the visualizations are in the DOM, so + // we wait for the event loop to flush before telling reporting to continue. This + // seems to correct a timing issue that was causing reporting to occasionally + // capture the first visualization before it was actually in the DOM. + // Note: 100 proved too short, see https://github.com/elastic/kibana/issues/22581, + // bumping to 250. + const hackyWaitForVisualizations = () => new Promise((r) => setTimeout(r, 250)); - // The renderComplete fires before the visualizations are in the DOM, so - // we wait for the event loop to flush before telling reporting to continue. This - // seems to correct a timing issue that was causing reporting to occasionally - // capture the first visualization before it was actually in the DOM. - // Note: 100 proved too short, see https://github.com/elastic/kibana/issues/22581, - // bumping to 250. - const hackyWaitForVisualizations = () => new Promise((r) => setTimeout(r, 250)); - - return Promise.all(renderedTasks).then(hackyWaitForVisualizations); - }, - args: [layout.selectors.renderComplete, loadDelay], + return Promise.all(renderedTasks).then(hackyWaitForVisualizations); }, - { context: CONTEXT_WAITFORRENDER }, - logger - ) - .then(() => { - logger.debug('rendering is complete'); - - span?.end(); - }); + args: [layout.selectors.renderComplete, loadDelay], + }, + { context: CONTEXT_WAITFORRENDER }, + eventLogger.kbnLogger + ); }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts index a7485545cdef0..b78f789a45564 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts @@ -5,11 +5,10 @@ * 2.0. */ -import apm from 'elastic-apm-node'; -import type { Logger } from '@kbn/core/server'; import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_WAITFORELEMENTSTOBEINDOM } from './constants'; +import { Actions, EventLogger } from './event_logger'; interface CompletedItemsCountParameters { context: string; @@ -37,12 +36,12 @@ const getCompletedItemsCount = ({ */ export const waitForVisualizations = async ( browser: HeadlessChromiumDriver, - logger: Logger, + eventLogger: EventLogger, timeout: number, toEqual: number, layout: Layout ): Promise => { - const span = apm.startSpan('wait_for_visualizations', 'wait'); + const logger = eventLogger.kbnLogger; const { renderComplete: renderCompleteSelector } = layout.selectors; logger.debug(`waiting for ${toEqual} rendered elements to be in the DOM`); @@ -56,11 +55,9 @@ export const waitForVisualizations = async ( logger.debug(`found ${toEqual} rendered elements in the DOM`); } catch (err) { - logger.error(err); + eventLogger.error(err, Actions.WAIT_VISUALIZATIONS); throw new Error( `An error occurred when trying to wait for ${toEqual} visualizations to finish rendering. ${err.message}` ); } - - span?.end(); }; From 7d85baf24b5bfcbe6785ba464b1e2df6ab7f44e4 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Mon, 18 Apr 2022 07:44:37 -0700 Subject: [PATCH 02/28] unique id for each pipeline flow --- .../server/formats/pdf/pdf_maker/index.ts | 6 +- .../server/screenshots/event_logger/index.ts | 210 +++++++++--------- .../screenshots/get_element_position_data.ts | 4 + .../server/screenshots/get_number_of_items.ts | 6 +- .../server/screenshots/get_render_errors.ts | 15 +- .../server/screenshots/get_screenshots.ts | 12 +- .../server/screenshots/index.ts | 18 +- .../server/screenshots/inject_css.ts | 5 +- .../server/screenshots/observable.ts | 2 +- 9 files changed, 146 insertions(+), 132 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts index 5c7b83b4cc5f2..b9c01ff82c76b 100644 --- a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts +++ b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts @@ -28,14 +28,14 @@ export async function pngsToPdf({ packageInfo, eventLogger, }: PngsToPdfArgs): Promise<{ buffer: Buffer; pages: number }> { - eventLogger.pdfBegin(); + eventLogger.pdfStart(); const pdfMaker = new PdfMaker(layout, logo, packageInfo, eventLogger.kbnLogger); if (title) { pdfMaker.setTitle(title); } results.forEach((result) => { result.screenshots.forEach((png) => { - eventLogger.addPdfImageBegin(); + eventLogger.addPdfImageStart(); pdfMaker.addImage(png.data, { title: png.title ?? undefined, description: png.description ?? undefined, @@ -46,7 +46,7 @@ export async function pngsToPdf({ let buffer: Uint8Array | null = null; try { - eventLogger.compilePdfBegin(); + eventLogger.compilePdfStart(); buffer = await pdfMaker.generate(); eventLogger.compilePdfEnd(); diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index f5eb66499e305..31e14e8abcfed 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -5,6 +5,7 @@ * 2.0. */ +import uuid from 'uuid'; import apm from 'elastic-apm-node'; import { Logger, LogMeta } from '@kbn/core/server'; import { CaptureResult } from '..'; @@ -14,12 +15,11 @@ import { Screenshot } from '../get_screenshots'; export enum Actions { SCREENSHOTTING = 'screenshot-pipeline', PDF = 'generate-pdf', - CREATE_LAYOUT = 'create-layout', CREATE_PAGE = 'create-page', GET_ELEMENT_POSITION_DATA = 'get-element-position-data', GET_NUMBER_OF_ITEMS = 'get-number-of-items', GET_RENDER_ERRORS = 'get-render-errors', - GET_SCREENSHOTS = 'get-screenshots', + GET_SCREENSHOT = 'get-screenshots', GET_TIMERANGE = 'get-timerange', INJECT_CSS = 'inject-css', OPEN_URL = 'open-url', @@ -41,23 +41,32 @@ enum SpanTypes { export interface ScreenshottingAction extends LogMeta { event?: { duration?: number; // number of nanoseconds from begin to end of an event + provider: typeof PLUGIN_ID; }; message: string; kibana: { screenshotting: { action: Actions; - // flow_id: string; // TODO random uuid to trace a pipeline flow - // is_pdf: boolean; // TODO + session_id: string; + + // chromium stats cpu?: number; cpu_percentage?: number; memory?: number; memory_mb?: number; + + // screenshotting stats items_count?: number; byte_length?: number; + element_positions?: number; + screenshot_current?: number; + screenshot_total?: number; // should match element_positions + render_errors?: number; + + // pdf stats byte_length_pdf?: number; pdf_pages?: number; - render_errors?: number; }; }; } @@ -75,22 +84,27 @@ interface PdfEndOptions { } interface RenderErrorsOptions { - renderErrors: number; + renderErrors?: number; } interface NumberOfItemsOptions { itemsCount: number; } +interface GetScreenshotOptions { + current: number; + total: number; + byteLength?: number; +} + type SpanEntity = | 'addPdfImage' | 'compilePdf' - | 'createLayout' | 'createPage' | 'getElementPositionData' | 'getNumberOfItems' | 'getRenderErrors' - | 'getScreenshots' + | 'getScreenshot' | 'getTimeRange' | 'injectCss' | 'openUrl' @@ -100,29 +114,32 @@ type SpanEntity = type TransactionEntity = 'generatePdf' | 'screenshotting'; -type LogAdapter = ( - message: string, - event: ScreenshottingAction['kibana']['screenshotting'], - startTime?: Date | undefined -) => void; - -function logAdapter(logger: Logger) { - const log: LogAdapter = ( - message: string, - event: ScreenshottingAction['kibana']['screenshotting'], - startTime?: Date | undefined - ) => { +type SimpleEvent = Omit; + +type LogAdapter = (message: string, event: SimpleEvent, startTime?: Date | undefined) => void; + +function logAdapter(logger: Logger, suffix: 'start' | 'complete', sessionId: string) { + const log: LogAdapter = (message, event, startTime) => { let duration: number | undefined; if (startTime != null) { const start = startTime.valueOf(); duration = new Date(Date.now()).valueOf() - start.valueOf(); } - logger.debug(message, { + const interpretedAction = (event.action + `-${suffix}`) as Actions; + const logData: ScreenshottingAction = { message, - kibana: { screenshotting: event }, + kibana: { + screenshotting: { + ...event, + action: interpretedAction, + session_id: sessionId, + }, + }, event: { duration, provider: PLUGIN_ID }, - }); + }; + logger.debug(message, logData); + return logData; }; return log; } @@ -134,12 +151,11 @@ export class EventLogger { private spans: Record = { addPdfImage: null, compilePdf: null, - createLayout: null, createPage: null, getElementPositionData: null, getNumberOfItems: null, getRenderErrors: null, - getScreenshots: null, + getScreenshot: null, getTimeRange: null, injectCss: null, openUrl: null, @@ -153,12 +169,15 @@ export class EventLogger { generatePdf: null, }; - private logEventData: ReturnType; + private sessionId: string; // identifier to track all logs from one screenshotting flow + private logEventStart: LogAdapter; + private logEventEnd: LogAdapter; private timings: Partial> = {}; constructor(private readonly logger: Logger) { - this.logEventData = logAdapter(logger.get('events')); - // TODO flow_id + this.sessionId = uuid.v4(); + this.logEventStart = logAdapter(logger.get('events'), 'start', this.sessionId); + this.logEventEnd = logAdapter(logger.get('events'), 'complete', this.sessionId); } private startTiming(a: Actions) { @@ -184,9 +203,9 @@ export class EventLogger { * * @returns void */ - public screenshottingBegin() { + public screenshottingStart() { this.transactions.screenshotting = apm.startTransaction(Actions.SCREENSHOTTING, PLUGIN_ID); - this.logEventData( + this.logEventStart( 'screenshot-pipeline starting', { action: Actions.SCREENSHOTTING } // ); @@ -196,7 +215,7 @@ export class EventLogger { /** * Signal when the screenshotting pipeline finishes * - * @param {CaptureResult} [TODO:name] - [TODO:description] + * @param {CaptureResult} results - outcome of screenshotting pipeline * @returns void */ public screenshottingEnd({ metrics, results }: CaptureResult) { @@ -212,7 +231,7 @@ export class EventLogger { this.transactions.screenshotting?.setLabel('byte-length', byteLength, false); this.transactions.screenshotting?.end(); - this.logEventData( + this.logEventEnd( 'screenshot-pipeline finished', { action: Actions.SCREENSHOTTING, byte_length: byteLength, cpu, memory }, this.timings[Actions.SCREENSHOTTING] @@ -224,9 +243,9 @@ export class EventLogger { * * @returns void */ - public pdfBegin() { + public pdfStart() { this.transactions.generatePdf = apm.startTransaction(Actions.PDF, PLUGIN_ID); - this.logEventData( + this.logEventStart( 'pdf generation starting', { action: Actions.PDF } // ); @@ -236,6 +255,7 @@ export class EventLogger { /** * Signal when PdfMaker generation finishes * + * @param {PdfEndOptions} - outcome of pdf generation * @returns void */ public pdfEnd({ byteLengthPdf, pdfPages }: PdfEndOptions) { @@ -243,7 +263,7 @@ export class EventLogger { this.transactions.generatePdf?.setLabel('pdf-pages', pdfPages, false); this.transactions.generatePdf?.end(); - this.logEventData( + this.logEventEnd( 'pdf generation finished', { action: Actions.PDF, @@ -256,54 +276,33 @@ export class EventLogger { // Methods for spans - public createLayoutBegin() { - this.spans.createLayout = this.transactions.screenshotting?.startSpan( - Actions.CREATE_LAYOUT, - SpanTypes.SETUP - ); - this.logEventData( - 'create-layout starting', - { action: Actions.CREATE_LAYOUT } // - ); - this.startTiming(Actions.CREATE_LAYOUT); - } - - public createLayoutEnd() { - this.spans.createLayout?.end(); - this.logEventData( - 'create-layout finished', - { action: Actions.CREATE_LAYOUT }, - this.timings[Actions.CREATE_LAYOUT] - ); - } - - public getElementPositionDataBegin() { + public getElementPositionsStart() { this.spans.getElementPositionData = this.transactions.screenshotting?.startSpan( Actions.GET_ELEMENT_POSITION_DATA, SpanTypes.READ ); - this.logEventData( + this.logEventStart( 'getting element position data', { action: Actions.GET_ELEMENT_POSITION_DATA } // ); this.startTiming(Actions.GET_ELEMENT_POSITION_DATA); } - public getElementPositionDataEnd() { + public getElementPositionsEnd({ elementPositions }: { elementPositions: number }) { this.spans.getElementPositionData?.end(); - this.logEventData( + this.logEventEnd( 'element position data read', - { action: Actions.GET_ELEMENT_POSITION_DATA }, + { action: Actions.GET_ELEMENT_POSITION_DATA, element_positions: elementPositions }, this.timings[Actions.GET_ELEMENT_POSITION_DATA] ); } - public getNumberOfItemsBegin() { + public getNumberOfItemsStart() { this.spans.getNumberOfItems = this.transactions.screenshotting?.startSpan( Actions.GET_NUMBER_OF_ITEMS, SpanTypes.READ ); - this.logEventData( + this.logEventStart( 'getting number of visualization items', { action: Actions.GET_NUMBER_OF_ITEMS } // ); @@ -312,7 +311,7 @@ export class EventLogger { public getNumberOfItemsEnd({ itemsCount }: NumberOfItemsOptions) { this.spans.getNumberOfItems?.end(); - this.logEventData( + this.logEventEnd( 'received number of visualization items', { action: Actions.GET_NUMBER_OF_ITEMS, @@ -322,12 +321,12 @@ export class EventLogger { ); } - public getRenderErrorsBegin() { + public getRenderErrorsStart() { this.spans.getRenderErrors = this.transactions.screenshotting?.startSpan( Actions.GET_RENDER_ERRORS, SpanTypes.READ ); - this.logEventData( + this.logEventStart( 'starting scan for rendering errors', { action: Actions.GET_RENDER_ERRORS } // ); @@ -336,7 +335,7 @@ export class EventLogger { public getRenderErrorsEnd({ renderErrors }: RenderErrorsOptions) { this.spans.getRenderErrors?.end(); - this.logEventData( + this.logEventEnd( 'finished scanning for rendering errors', { action: Actions.GET_RENDER_ERRORS, @@ -346,33 +345,34 @@ export class EventLogger { ); } - public getScreenshotsBegin() { - this.spans.getScreenshots = this.transactions.screenshotting?.startSpan( - Actions.GET_SCREENSHOTS, + public getScreenshotStart({ current, total }: GetScreenshotOptions) { + this.spans.getScreenshot = this.transactions.screenshotting?.startSpan( + Actions.GET_SCREENSHOT, SpanTypes.READ ); - this.logEventData( - 'capturing screenshots', - { action: Actions.GET_SCREENSHOTS } // - ); - this.startTiming(Actions.GET_SCREENSHOTS); + this.logEventStart('capturing single screenshot', { + action: Actions.GET_SCREENSHOT, + screenshot_current: current, + screenshot_total: total, + }); + this.startTiming(Actions.GET_SCREENSHOT); } - public getScreenshotsEnd() { - this.spans.getScreenshots?.end(); - this.logEventData( - 'screenshots captured', - { action: Actions.GET_SCREENSHOTS }, - this.timings[Actions.GET_SCREENSHOTS] + public getScreenshotEnd({ byteLength }: GetScreenshotOptions) { + this.spans.getScreenshot?.end(); + this.logEventEnd( + 'single screenshot captured', + { action: Actions.GET_SCREENSHOT, byte_length: byteLength }, + this.timings[Actions.GET_SCREENSHOT] ); } - public getTimeRangeBegin() { + public getTimeRangeStart() { this.spans.getTimeRange = this.transactions.screenshotting?.startSpan( Actions.GET_TIMERANGE, SpanTypes.READ ); - this.logEventData( + this.logEventStart( 'getting time range', { action: Actions.GET_TIMERANGE } // ); @@ -381,19 +381,19 @@ export class EventLogger { public getTimeRangeEnd() { this.spans.getTimeRange?.end(); - this.logEventData( + this.logEventEnd( 'received time range', { action: Actions.GET_TIMERANGE }, this.timings[Actions.GET_TIMERANGE] ); } - public injectCssBegin() { + public injectCssStart() { this.spans.injectCss = this.transactions.screenshotting?.startSpan( Actions.INJECT_CSS, SpanTypes.CORRECT ); - this.logEventData( + this.logEventStart( 'injecting css', { action: Actions.INJECT_CSS } // ); @@ -402,19 +402,19 @@ export class EventLogger { public injectCssEnd() { this.spans.injectCss?.end(); - this.logEventData( + this.logEventEnd( 'finished injecting css', { action: Actions.INJECT_CSS }, this.timings[Actions.INJECT_CSS] ); } - public openUrlBegin() { + public openUrlStart() { this.spans.openUrl = this.transactions.screenshotting?.startSpan( Actions.OPEN_URL, SpanTypes.WAIT ); - this.logEventData( + this.logEventStart( 'opening url', { action: Actions.OPEN_URL } // ); @@ -423,19 +423,19 @@ export class EventLogger { public openUrlEnd() { this.spans.openUrl?.end(); - this.logEventData( + this.logEventEnd( 'finished opening url', { action: Actions.OPEN_URL }, this.timings[Actions.OPEN_URL] ); } - public positionElementsBegin() { + public positionElementsStart() { this.spans.positionElements = this.transactions.screenshotting?.startSpan( Actions.REPOSITION, SpanTypes.CORRECT ); - this.logEventData( + this.logEventStart( 'positioning elements', { action: Actions.REPOSITION } // ); @@ -444,19 +444,19 @@ export class EventLogger { public positionElementsEnd() { this.spans.positionElements?.end(); - this.logEventData( + this.logEventEnd( 'finished positioning elements', { action: Actions.REPOSITION }, this.timings[Actions.REPOSITION] ); } - public waitForRenderBegin() { + public waitForRenderStart() { this.spans.waitForRender = this.transactions.screenshotting?.startSpan( Actions.WAIT_RENDER, SpanTypes.WAIT ); - this.logEventData( + this.logEventStart( 'waiting for render to complete', { action: Actions.WAIT_RENDER } // ); @@ -465,19 +465,19 @@ export class EventLogger { public waitForRenderEnd() { this.spans.waitForRender?.end(); - this.logEventData( + this.logEventEnd( 'finished waiting for render to complete', { action: Actions.WAIT_RENDER }, this.timings[Actions.WAIT_RENDER] ); } - public waitForVisualizationBegin() { + public waitForVisualizationStart() { this.spans.waitForVisualization = this.transactions.screenshotting?.startSpan( Actions.WAIT_VISUALIZATIONS, SpanTypes.WAIT ); - this.logEventData( + this.logEventStart( 'waiting for visualizations', { action: Actions.WAIT_VISUALIZATIONS } // ); @@ -486,19 +486,19 @@ export class EventLogger { public waitForVisualizationEnd() { this.spans.waitForVisualization?.end(); - this.logEventData( + this.logEventEnd( 'finished waiting for visualizations', { action: Actions.WAIT_VISUALIZATIONS }, this.timings[Actions.WAIT_VISUALIZATIONS] ); } - public addPdfImageBegin() { + public addPdfImageStart() { this.spans.addPdfImage = this.transactions.generatePdf?.startSpan( Actions.ADD_IMAGE, SpanTypes.OUTPUT ); - this.logEventData( + this.logEventStart( 'adding pdf image', { action: Actions.ADD_IMAGE } // ); @@ -507,19 +507,19 @@ export class EventLogger { public addPdfImageEnd() { this.spans.addPdfImage?.end(); - this.logEventData( + this.logEventEnd( 'pdf image added', { action: Actions.ADD_IMAGE }, this.timings[Actions.ADD_IMAGE] ); } - public compilePdfBegin() { + public compilePdfStart() { this.spans.compilePdf = this.transactions.generatePdf?.startSpan( Actions.COMPILE, SpanTypes.OUTPUT ); - this.logEventData( + this.logEventStart( 'compiling pdf file', { action: Actions.COMPILE } // ); @@ -528,7 +528,7 @@ export class EventLogger { public compilePdfEnd() { this.spans.compilePdf?.end(); - this.logEventData( + this.logEventEnd( 'pdf file compiled', { action: Actions.COMPILE }, this.timings[Actions.COMPILE] diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index 9c8f2460e9434..8e69d423ac92e 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -38,6 +38,8 @@ export const getElementPositionAndAttributes = async ( eventLogger: EventLogger, layout: Layout ): Promise => { + eventLogger.getElementPositionsStart(); + const { screenshot: screenshotSelector } = layout.selectors; // data-shared-items-container let elementsPositionAndAttributes: ElementsPositionAndAttribute[] | null; try { @@ -88,5 +90,7 @@ export const getElementPositionAndAttributes = async ( elementsPositionAndAttributes = null; } + eventLogger.getElementPositionsEnd({ elementsPositions: elementsPositionAndAttributes?.length }); + return elementsPositionAndAttributes; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts index 0798d3a519c70..01e60a3b82c3b 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts @@ -16,11 +16,13 @@ export const getNumberOfItems = async ( timeout: number, layout: Layout ): Promise => { - const logger = eventLogger.kbnLogger; + eventLogger.getNumberOfItemsStart(); + const { renderComplete: renderCompleteSelector, itemsCountAttribute } = layout.selectors; let itemsCount: number; try { + const logger = eventLogger.kbnLogger; // the dashboard is using the `itemsCountAttribute` attribute to let us // know how many items to expect since gridster incrementally adds panels // we have to use this hint to wait for all of them @@ -58,5 +60,7 @@ export const getNumberOfItems = async ( ); } + eventLogger.getNumberOfItemsEnd({ itemsCount }); + return itemsCount; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts index 6b36b28fe1383..6e56103e93e1f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts @@ -15,7 +15,9 @@ export const getRenderErrors = async ( eventLogger: EventLogger, layout: Layout ): Promise => { - const { kbnLogger: logger } = eventLogger; + eventLogger.getRenderErrorsStart(); + + const { kbnLogger } = eventLogger; const errorsFound: undefined | string[] = await browser.evaluate( { fn: (errorSelector, errorAttribute) => { @@ -34,14 +36,15 @@ export const getRenderErrors = async ( args: [layout.selectors.renderError, layout.selectors.renderErrorAttribute], }, { context: CONTEXT_GETRENDERERRORS }, - logger + kbnLogger ); - if (errorsFound?.length) { - logger.warn( - `Found ${errorsFound.length} error messages. See report object for more information.` - ); + const renderErrors = errorsFound?.length; + if (renderErrors) { + kbnLogger.warn(`Found ${renderErrors} error messages. See report object for more information.`); } + eventLogger.getRenderErrorsEnd({ renderErrors }); + return errorsFound; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index 50b6776dd2722..b2bb5e7814493 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -31,12 +31,14 @@ export const getScreenshots = async ( eventLogger: EventLogger, elementsPositionAndAttributes: ElementsPositionAndAttribute[] ): Promise => { - const { kbnLogger: logger } = eventLogger; - logger.info(`taking screenshots`); + const { kbnLogger } = eventLogger; + kbnLogger.info(`taking screenshots`); const screenshots: Screenshot[] = []; - for (let i = 0; i < elementsPositionAndAttributes.length; i++) { + const size = elementsPositionAndAttributes.length; + for (let i = 0; i < size; i++) { + eventLogger.getScreenshotStart({ current: size, total: i + 1 }); const item = elementsPositionAndAttributes[i]; const data = await browser.screenshot(item.position); @@ -50,9 +52,11 @@ export const getScreenshots = async ( title: item.attributes.title, description: item.attributes.description, }); + + eventLogger.getScreenshotEnd({ byteLength: data.byteLength, current: size, total: i + 1 }); } - logger.info(`screenshots taken: ${screenshots.length}`); + kbnLogger.info(`screenshots taken: ${screenshots.length}`); return screenshots; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/index.ts b/x-pack/plugins/screenshotting/server/screenshots/index.ts index 5537ec94f1345..758b49afeb24b 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/index.ts @@ -94,7 +94,6 @@ const DEFAULT_SETUP_RESULT = { export class Screenshots { private semaphore: Semaphore; - private eventLogger: EventLogger; constructor( private readonly browserDriverFactory: HeadlessChromiumDriverFactory, @@ -103,22 +102,20 @@ export class Screenshots { private readonly http: HttpServiceSetup, private readonly config: ConfigType ) { - this.eventLogger = new EventLogger(logger); this.semaphore = new Semaphore(config.poolSize); } private createLayout(options: CaptureOptions): Layout { - this.eventLogger.createLayoutBegin(); const layout = createLayout(options.layout ?? {}); this.logger.debug(`Layout: width=${layout.width} height=${layout.height}`); - this.eventLogger.createLayoutEnd(); return layout; } private captureScreenshots( layout: Layout, - options: ScreenshotObservableOptions + options: ScreenshotObservableOptions, + eventLogger: EventLogger ): Observable { const { browserTimezone } = options; @@ -137,7 +134,7 @@ export class Screenshots { const screen = new ScreenshotObservableHandler( driver, this.config, - this.eventLogger, + eventLogger, layout, options ); @@ -220,19 +217,20 @@ export class Screenshots { getScreenshots(options: PdfScreenshotOptions): Observable; getScreenshots(options: ScreenshotOptions): Observable; getScreenshots(options: ScreenshotOptions): Observable { - this.eventLogger.screenshottingBegin(); + const eventLogger = new EventLogger(this.logger); + eventLogger.screenshottingStart(); const layout = this.createLayout(options); const captureOptions = this.getCaptureOptions(options); - return this.captureScreenshots(layout, captureOptions).pipe( + return this.captureScreenshots(layout, captureOptions, eventLogger).pipe( tap((results) => { - this.eventLogger.screenshottingEnd(results); + eventLogger.screenshottingEnd(results); }), mergeMap((result) => { switch (options.format) { case 'pdf': - return toPdf(this.eventLogger, this.packageInfo, layout, options, result); + return toPdf(eventLogger, this.packageInfo, layout, options, result); default: return toPng(result); } diff --git a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts index cbcab3889d2a3..b866d19750ce7 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts @@ -19,12 +19,13 @@ export const injectCustomCss = async ( eventLogger: EventLogger, layout: Layout ): Promise => { - eventLogger.injectCssBegin(); - const filePath = layout.getCssOverridesPath(); if (!filePath) { return; } + + eventLogger.injectCssStart(); + const buffer = await fsp.readFile(filePath); try { await browser.evaluate( diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index 2e2ef88119b4f..226011515544f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -192,7 +192,7 @@ export class ScreenshotObservableHandler { // allows for them to be displayed properly in many cases await injectCustomCss(driver, logger, layout); - this.eventLogger.positionElementsBegin(); + this.eventLogger.positionElementsStart(); // position panel elements for print layout await layout.positionElements?.(driver, logger.kbnLogger); this.eventLogger.positionElementsEnd(); From 0248d85269ef967ba6780e54440ccc5f81de8cd4 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Mon, 18 Apr 2022 10:58:58 -0700 Subject: [PATCH 03/28] fix open_url logging --- .../screenshotting/server/screenshots/event_logger/index.ts | 2 +- .../server/screenshots/get_element_position_data.ts | 2 +- x-pack/plugins/screenshotting/server/screenshots/index.ts | 4 ++-- .../plugins/screenshotting/server/screenshots/observable.ts | 3 ++- x-pack/plugins/screenshotting/server/screenshots/open_url.ts | 4 ++++ 5 files changed, 10 insertions(+), 5 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 31e14e8abcfed..1d240a2f8abb7 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -288,7 +288,7 @@ export class EventLogger { this.startTiming(Actions.GET_ELEMENT_POSITION_DATA); } - public getElementPositionsEnd({ elementPositions }: { elementPositions: number }) { + public getElementPositionsEnd({ elementPositions }: { elementPositions?: number }) { this.spans.getElementPositionData?.end(); this.logEventEnd( 'element position data read', diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index 8e69d423ac92e..d4da179d3b1ee 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -90,7 +90,7 @@ export const getElementPositionAndAttributes = async ( elementsPositionAndAttributes = null; } - eventLogger.getElementPositionsEnd({ elementsPositions: elementsPositionAndAttributes?.length }); + eventLogger.getElementPositionsEnd({ elementPositions: elementsPositionAndAttributes?.length }); return elementsPositionAndAttributes; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/index.ts b/x-pack/plugins/screenshotting/server/screenshots/index.ts index 758b49afeb24b..aa9540632f829 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/index.ts @@ -41,7 +41,7 @@ import { } from '../formats'; import type { Layout } from '../layouts'; import { createLayout } from '../layouts'; -import { EventLogger } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; import type { ScreenshotObservableOptions, ScreenshotObservableResult } from './observable'; import { ScreenshotObservableHandler, UrlOrUrlWithContext } from './observable'; import { Semaphore } from './semaphore'; @@ -145,7 +145,7 @@ export class Screenshots { catchError((error) => { screen.checkPageIsOpen(); // this fails the job if the browser has closed - this.logger.error(error); + eventLogger.error(error, Actions.SCREENSHOTTING); return of({ ...DEFAULT_SETUP_RESULT, error }); // allow failover screenshot capture }), takeUntil(unexpectedExit$), diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index 226011515544f..fd84a9af30af2 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -13,7 +13,7 @@ import type { Context, HeadlessChromiumDriver } from '../browsers'; import { DEFAULT_VIEWPORT, getChromiumDisconnectedError } from '../browsers'; import { ConfigType, durationToNumber as toNumber } from '../config'; import type { Layout } from '../layouts'; -import { EventLogger } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; import type { ElementsPositionAndAttribute } from './get_element_position_data'; import { getElementPositionAndAttributes } from './get_element_position_data'; import { getNumberOfItems } from './get_number_of_items'; @@ -229,6 +229,7 @@ export class ScreenshotObservableHandler { try { screenshots = await getScreenshots(this.driver, this.eventLogger, elements); } catch (e) { + this.eventLogger.error(e, Actions.GET_SCREENSHOT); throw new errors.FailedToCaptureScreenshot(e.message); } const { timeRange, error: setupError, renderErrors } = data; diff --git a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts index 3d55b8e770c0f..ee1a4cf462576 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts @@ -19,6 +19,8 @@ export const openUrl = async ( context: Context, headers: Headers ): Promise => { + eventLogger.openUrlStart(); + // If we're moving to another page in the app, we'll want to wait for the app to tell us // it's loaded the next page. const page = index + 1; @@ -30,4 +32,6 @@ export const openUrl = async ( eventLogger.error(err, Actions.OPEN_URL); throw new Error(`An error occurred when trying to open the Kibana URL: ${err.message}`); } + + eventLogger.openUrlEnd(); }; From 64694f6d14793283e426e4771d5f796ee2e00f6a Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Mon, 18 Apr 2022 11:37:27 -0700 Subject: [PATCH 04/28] add comments --- .../server/screenshots/event_logger/index.ts | 148 +++++++----------- 1 file changed, 58 insertions(+), 90 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 1d240a2f8abb7..f10acd5c9d28e 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -14,18 +14,17 @@ import { Screenshot } from '../get_screenshots'; export enum Actions { SCREENSHOTTING = 'screenshot-pipeline', - PDF = 'generate-pdf', - CREATE_PAGE = 'create-page', + OPEN_URL = 'open-url', GET_ELEMENT_POSITION_DATA = 'get-element-position-data', GET_NUMBER_OF_ITEMS = 'get-number-of-items', GET_RENDER_ERRORS = 'get-render-errors', - GET_SCREENSHOT = 'get-screenshots', GET_TIMERANGE = 'get-timerange', INJECT_CSS = 'inject-css', - OPEN_URL = 'open-url', REPOSITION = 'position-elements', WAIT_RENDER = 'wait-for-render', WAIT_VISUALIZATIONS = 'wait-for-visualizations', + GET_SCREENSHOT = 'get-screenshots', + PDF = 'generate-pdf', ADD_IMAGE = 'add-pdf-image', COMPILE = 'compile-pdf', } @@ -78,23 +77,10 @@ interface ErrorAction { type?: string; } -interface PdfEndOptions { - byteLengthPdf: number; - pdfPages: number; -} - -interface RenderErrorsOptions { - renderErrors?: number; -} - -interface NumberOfItemsOptions { - itemsCount: number; -} - interface GetScreenshotOptions { - current: number; - total: number; - byteLength?: number; + current: number; // current screenshot to be taken + total: number; // total number of screenshots to be taken + byteLength?: number; // byte length of completed completed current screenshot } type SpanEntity = @@ -188,8 +174,6 @@ export class EventLogger { byteLength + screenshot.data.byteLength; /** - * Helper to return the original logger - * * @returns Logger */ public get kbnLogger() { @@ -199,23 +183,20 @@ export class EventLogger { // Methods for transactions /** - * Signal when the screenshotting pipeline begins + * Signal when the overall screenshotting pipeline begins * * @returns void */ public screenshottingStart() { this.transactions.screenshotting = apm.startTransaction(Actions.SCREENSHOTTING, PLUGIN_ID); - this.logEventStart( - 'screenshot-pipeline starting', - { action: Actions.SCREENSHOTTING } // - ); + this.logEventStart('screenshot-pipeline starting', { action: Actions.SCREENSHOTTING }); this.startTiming(Actions.SCREENSHOTTING); } /** - * Signal when the screenshotting pipeline finishes + * Signal when the overall screenshotting pipeline finishes * - * @param {CaptureResult} results - outcome of screenshotting pipeline + * @param {CaptureResult} - outcome of screenshotting pipeline * @returns void */ public screenshottingEnd({ metrics, results }: CaptureResult) { @@ -238,27 +219,18 @@ export class EventLogger { ); } - /** - * Signal when PdfMaker generation starts - * - * @returns void - */ public pdfStart() { this.transactions.generatePdf = apm.startTransaction(Actions.PDF, PLUGIN_ID); - this.logEventStart( - 'pdf generation starting', - { action: Actions.PDF } // - ); + this.logEventStart('pdf generation starting', { action: Actions.PDF }); this.startTiming(Actions.PDF); } /** - * Signal when PdfMaker generation finishes - * - * @param {PdfEndOptions} - outcome of pdf generation + * @param .byteLengthPdf - length of bytes of the PDF file + * @param .pdfPages - number of pages in the PDF file * @returns void */ - public pdfEnd({ byteLengthPdf, pdfPages }: PdfEndOptions) { + public pdfEnd({ byteLengthPdf, pdfPages }: { byteLengthPdf: number; pdfPages: number }) { this.transactions.generatePdf?.setLabel('byte-length', byteLengthPdf, false); this.transactions.generatePdf?.setLabel('pdf-pages', pdfPages, false); this.transactions.generatePdf?.end(); @@ -281,13 +253,16 @@ export class EventLogger { Actions.GET_ELEMENT_POSITION_DATA, SpanTypes.READ ); - this.logEventStart( - 'getting element position data', - { action: Actions.GET_ELEMENT_POSITION_DATA } // - ); + this.logEventStart('getting element position data', { + action: Actions.GET_ELEMENT_POSITION_DATA, + }); this.startTiming(Actions.GET_ELEMENT_POSITION_DATA); } + /** + * @param .elementPositions - number of elements that have a position to know about + * @returns void + */ public getElementPositionsEnd({ elementPositions }: { elementPositions?: number }) { this.spans.getElementPositionData?.end(); this.logEventEnd( @@ -302,14 +277,17 @@ export class EventLogger { Actions.GET_NUMBER_OF_ITEMS, SpanTypes.READ ); - this.logEventStart( - 'getting number of visualization items', - { action: Actions.GET_NUMBER_OF_ITEMS } // - ); + this.logEventStart('getting number of visualization items', { + action: Actions.GET_NUMBER_OF_ITEMS, + }); this.startTiming(Actions.GET_NUMBER_OF_ITEMS); } - public getNumberOfItemsEnd({ itemsCount }: NumberOfItemsOptions) { + /** + * @param .itemsCount - number of renderable items found on the page + * @returns void + */ + public getNumberOfItemsEnd({ itemsCount }: { itemsCount: number }) { this.spans.getNumberOfItems?.end(); this.logEventEnd( 'received number of visualization items', @@ -326,14 +304,15 @@ export class EventLogger { Actions.GET_RENDER_ERRORS, SpanTypes.READ ); - this.logEventStart( - 'starting scan for rendering errors', - { action: Actions.GET_RENDER_ERRORS } // - ); + this.logEventStart('starting scan for rendering errors', { action: Actions.GET_RENDER_ERRORS }); this.startTiming(Actions.GET_RENDER_ERRORS); } - public getRenderErrorsEnd({ renderErrors }: RenderErrorsOptions) { + /** + * @param .renderErrors - total number of render errors found on the page + * @returns void + */ + public getRenderErrorsEnd({ renderErrors }: { renderErrors?: number }) { this.spans.getRenderErrors?.end(); this.logEventEnd( 'finished scanning for rendering errors', @@ -345,6 +324,10 @@ export class EventLogger { ); } + /** + * @param GetScreenshotOptions - context of the screenshot to be taken + * @returns void + */ public getScreenshotStart({ current, total }: GetScreenshotOptions) { this.spans.getScreenshot = this.transactions.screenshotting?.startSpan( Actions.GET_SCREENSHOT, @@ -358,11 +341,20 @@ export class EventLogger { this.startTiming(Actions.GET_SCREENSHOT); } - public getScreenshotEnd({ byteLength }: GetScreenshotOptions) { + /** + * @param GetScreenshotOptions - context of the screenshot taken + * @returns void + */ + public getScreenshotEnd({ byteLength, current, total }: GetScreenshotOptions) { this.spans.getScreenshot?.end(); this.logEventEnd( 'single screenshot captured', - { action: Actions.GET_SCREENSHOT, byte_length: byteLength }, + { + action: Actions.GET_SCREENSHOT, + byte_length: byteLength, + screenshot_current: current, + screenshot_total: total, + }, this.timings[Actions.GET_SCREENSHOT] ); } @@ -372,10 +364,7 @@ export class EventLogger { Actions.GET_TIMERANGE, SpanTypes.READ ); - this.logEventStart( - 'getting time range', - { action: Actions.GET_TIMERANGE } // - ); + this.logEventStart('getting time range', { action: Actions.GET_TIMERANGE }); this.startTiming(Actions.GET_TIMERANGE); } @@ -393,10 +382,7 @@ export class EventLogger { Actions.INJECT_CSS, SpanTypes.CORRECT ); - this.logEventStart( - 'injecting css', - { action: Actions.INJECT_CSS } // - ); + this.logEventStart('injecting css', { action: Actions.INJECT_CSS }); this.startTiming(Actions.INJECT_CSS); } @@ -414,10 +400,7 @@ export class EventLogger { Actions.OPEN_URL, SpanTypes.WAIT ); - this.logEventStart( - 'opening url', - { action: Actions.OPEN_URL } // - ); + this.logEventStart('opening url', { action: Actions.OPEN_URL }); this.startTiming(Actions.OPEN_URL); } @@ -435,10 +418,7 @@ export class EventLogger { Actions.REPOSITION, SpanTypes.CORRECT ); - this.logEventStart( - 'positioning elements', - { action: Actions.REPOSITION } // - ); + this.logEventStart('positioning elements', { action: Actions.REPOSITION }); this.startTiming(Actions.REPOSITION); } @@ -456,10 +436,7 @@ export class EventLogger { Actions.WAIT_RENDER, SpanTypes.WAIT ); - this.logEventStart( - 'waiting for render to complete', - { action: Actions.WAIT_RENDER } // - ); + this.logEventStart('waiting for render to complete', { action: Actions.WAIT_RENDER }); this.startTiming(Actions.WAIT_RENDER); } @@ -477,10 +454,7 @@ export class EventLogger { Actions.WAIT_VISUALIZATIONS, SpanTypes.WAIT ); - this.logEventStart( - 'waiting for visualizations', - { action: Actions.WAIT_VISUALIZATIONS } // - ); + this.logEventStart('waiting for visualizations', { action: Actions.WAIT_VISUALIZATIONS }); this.startTiming(Actions.WAIT_VISUALIZATIONS); } @@ -498,10 +472,7 @@ export class EventLogger { Actions.ADD_IMAGE, SpanTypes.OUTPUT ); - this.logEventStart( - 'adding pdf image', - { action: Actions.ADD_IMAGE } // - ); + this.logEventStart('adding pdf image', { action: Actions.ADD_IMAGE }); this.startTiming(Actions.ADD_IMAGE); } @@ -519,10 +490,7 @@ export class EventLogger { Actions.COMPILE, SpanTypes.OUTPUT ); - this.logEventStart( - 'compiling pdf file', - { action: Actions.COMPILE } // - ); + this.logEventStart('compiling pdf file', { action: Actions.COMPILE }); this.startTiming(Actions.COMPILE); } From 75cba89771802bc328324d8904665cfccca21092 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Mon, 18 Apr 2022 12:24:34 -0700 Subject: [PATCH 05/28] add unit test --- .../screenshots/event_logger/index.test.ts | 194 ++++++++++++++++++ .../server/screenshots/event_logger/index.ts | 108 ++++++---- .../server/screenshots/wait_for_render.ts | 82 ++++---- .../screenshots/wait_for_visualizations.ts | 4 + 4 files changed, 315 insertions(+), 73 deletions(-) create mode 100644 x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts new file mode 100644 index 0000000000000..79536777d8495 --- /dev/null +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -0,0 +1,194 @@ +/* + * 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; you may not use this file except in compliance with the Elastic License + * 2.0. + */ + +import moment from 'moment'; +import { loggingSystemMock } from '@kbn/core/server/mocks'; +import { Actions, EventLogger } from '.'; + +describe('Event Logger', () => { + let eventLogger: EventLogger; + + beforeEach(() => { + const testDate = moment(new Date('2021-04-12T16:00:00.000Z')); + let walker = 1; + jest.spyOn(global.Date, 'now').mockImplementation(() => { + return testDate.add(walker++, 'seconds').valueOf(); + }); + + eventLogger = new EventLogger(loggingSystemMock.createLogger()); + }); + + it('creates logs for the events and includes durations and event payload data', () => { + const logs = []; + logs.push(eventLogger.screenshottingStart()); + logs.push(eventLogger.openUrlStart()); + logs.push(eventLogger.openUrlEnd()); + logs.push(eventLogger.getElementPositionsStart()); + logs.push(eventLogger.getElementPositionsEnd({ elementPositions: 44 })); + + logs.push(eventLogger.getNumberOfItemsStart()); + logs.push(eventLogger.getNumberOfItemsEnd({ itemsCount: 3 })); + logs.push(eventLogger.getRenderErrorsStart()); + logs.push(eventLogger.getRenderErrorsEnd({ renderErrors: 0 })); + logs.push(eventLogger.getTimeRangeStart()); + logs.push(eventLogger.getTimeRangeEnd()); + logs.push(eventLogger.injectCssStart()); + logs.push(eventLogger.injectCssEnd()); + logs.push(eventLogger.positionElementsStart()); + logs.push(eventLogger.positionElementsEnd()); + logs.push(eventLogger.waitForRenderStart()); + logs.push(eventLogger.waitForRenderEnd()); + logs.push(eventLogger.getScreenshotStart({ current: 1, total: 1 })); + logs.push(eventLogger.getScreenshotEnd({ byteLength: 4444, current: 1, total: 1 })); + logs.push(eventLogger.pdfStart()); + logs.push(eventLogger.addPdfImageStart()); + logs.push(eventLogger.addPdfImageEnd()); + logs.push(eventLogger.compilePdfStart()); + logs.push(eventLogger.compilePdfEnd()); + logs.push(eventLogger.pdfEnd({ pdfPages: 1, byteLengthPdf: 6666 })); + + const actionNames = logs.map((log) => ({ + event: log.kibana.screenshotting.action, + duration: log.event?.duration, + })); + expect(actionNames).toMatchInlineSnapshot(` + Array [ + Object { + "duration": undefined, + "event": "screenshot-pipeline-start", + }, + Object { + "duration": undefined, + "event": "open-url-start", + }, + Object { + "duration": 3000, + "event": "open-url-complete", + }, + Object { + "duration": undefined, + "event": "get-element-position-data-start", + }, + Object { + "duration": 5000, + "event": "get-element-position-data-complete", + }, + Object { + "duration": undefined, + "event": "get-number-of-items-start", + }, + Object { + "duration": 7000, + "event": "get-number-of-items-complete", + }, + Object { + "duration": undefined, + "event": "get-render-errors-start", + }, + Object { + "duration": 9000, + "event": "get-render-errors-complete", + }, + Object { + "duration": undefined, + "event": "get-timerange-start", + }, + Object { + "duration": 11000, + "event": "get-timerange-complete", + }, + Object { + "duration": undefined, + "event": "inject-css-start", + }, + Object { + "duration": 13000, + "event": "inject-css-complete", + }, + Object { + "duration": undefined, + "event": "position-elements-start", + }, + Object { + "duration": 15000, + "event": "position-elements-complete", + }, + Object { + "duration": undefined, + "event": "wait-for-render-start", + }, + Object { + "duration": 17000, + "event": "wait-for-render-complete", + }, + Object { + "duration": undefined, + "event": "get-screenshots-start", + }, + Object { + "duration": 19000, + "event": "get-screenshots-complete", + }, + Object { + "duration": undefined, + "event": "generate-pdf-start", + }, + Object { + "duration": undefined, + "event": "add-pdf-image-start", + }, + Object { + "duration": 22000, + "event": "add-pdf-image-complete", + }, + Object { + "duration": undefined, + "event": "compile-pdf-start", + }, + Object { + "duration": 24000, + "event": "compile-pdf-complete", + }, + Object { + "duration": 115000, + "event": "generate-pdf-complete", + }, + ] + `); + }); + + it('creates helpful error logs', () => { + const logs = []; + logs.push(eventLogger.screenshottingStart()); + logs.push(eventLogger.error(new Error('Something erroneous happened'), Actions.SCREENSHOTTING)); + + const actionNames = logs.map((log) => ({ + action: log.kibana.screenshotting.action, + message: log.message, + error: log.error, + })); + expect(actionNames).toMatchInlineSnapshot(` + Array [ + Object { + "action": "screenshot-pipeline-start", + "error": undefined, + "message": "screenshot-pipeline starting", + }, + Object { + "action": "screenshot-pipeline-error", + "error": Object { + "code": undefined, + "message": "Something erroneous happened", + "stack_trace": undefined, + "type": undefined, + }, + "message": "an error occurred", + }, + ] + `); + }); +}); diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index f10acd5c9d28e..ed24c18c7b1f8 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -102,7 +102,11 @@ type TransactionEntity = 'generatePdf' | 'screenshotting'; type SimpleEvent = Omit; -type LogAdapter = (message: string, event: SimpleEvent, startTime?: Date | undefined) => void; +type LogAdapter = ( + message: string, + event: SimpleEvent, + startTime?: Date | undefined +) => ScreenshottingAction; function logAdapter(logger: Logger, suffix: 'start' | 'complete', sessionId: string) { const log: LogAdapter = (message, event, startTime) => { @@ -189,8 +193,9 @@ export class EventLogger { */ public screenshottingStart() { this.transactions.screenshotting = apm.startTransaction(Actions.SCREENSHOTTING, PLUGIN_ID); - this.logEventStart('screenshot-pipeline starting', { action: Actions.SCREENSHOTTING }); this.startTiming(Actions.SCREENSHOTTING); + + return this.logEventStart('screenshot-pipeline starting', { action: Actions.SCREENSHOTTING }); } /** @@ -212,7 +217,7 @@ export class EventLogger { this.transactions.screenshotting?.setLabel('byte-length', byteLength, false); this.transactions.screenshotting?.end(); - this.logEventEnd( + return this.logEventEnd( 'screenshot-pipeline finished', { action: Actions.SCREENSHOTTING, byte_length: byteLength, cpu, memory }, this.timings[Actions.SCREENSHOTTING] @@ -221,8 +226,9 @@ export class EventLogger { public pdfStart() { this.transactions.generatePdf = apm.startTransaction(Actions.PDF, PLUGIN_ID); - this.logEventStart('pdf generation starting', { action: Actions.PDF }); this.startTiming(Actions.PDF); + + return this.logEventStart('pdf generation starting', { action: Actions.PDF }); } /** @@ -235,7 +241,7 @@ export class EventLogger { this.transactions.generatePdf?.setLabel('pdf-pages', pdfPages, false); this.transactions.generatePdf?.end(); - this.logEventEnd( + return this.logEventEnd( 'pdf generation finished', { action: Actions.PDF, @@ -253,10 +259,11 @@ export class EventLogger { Actions.GET_ELEMENT_POSITION_DATA, SpanTypes.READ ); - this.logEventStart('getting element position data', { + this.startTiming(Actions.GET_ELEMENT_POSITION_DATA); + + return this.logEventStart('getting element position data', { action: Actions.GET_ELEMENT_POSITION_DATA, }); - this.startTiming(Actions.GET_ELEMENT_POSITION_DATA); } /** @@ -265,7 +272,8 @@ export class EventLogger { */ public getElementPositionsEnd({ elementPositions }: { elementPositions?: number }) { this.spans.getElementPositionData?.end(); - this.logEventEnd( + + return this.logEventEnd( 'element position data read', { action: Actions.GET_ELEMENT_POSITION_DATA, element_positions: elementPositions }, this.timings[Actions.GET_ELEMENT_POSITION_DATA] @@ -277,10 +285,11 @@ export class EventLogger { Actions.GET_NUMBER_OF_ITEMS, SpanTypes.READ ); - this.logEventStart('getting number of visualization items', { + this.startTiming(Actions.GET_NUMBER_OF_ITEMS); + + return this.logEventStart('getting number of visualization items', { action: Actions.GET_NUMBER_OF_ITEMS, }); - this.startTiming(Actions.GET_NUMBER_OF_ITEMS); } /** @@ -289,7 +298,8 @@ export class EventLogger { */ public getNumberOfItemsEnd({ itemsCount }: { itemsCount: number }) { this.spans.getNumberOfItems?.end(); - this.logEventEnd( + + return this.logEventEnd( 'received number of visualization items', { action: Actions.GET_NUMBER_OF_ITEMS, @@ -304,8 +314,11 @@ export class EventLogger { Actions.GET_RENDER_ERRORS, SpanTypes.READ ); - this.logEventStart('starting scan for rendering errors', { action: Actions.GET_RENDER_ERRORS }); this.startTiming(Actions.GET_RENDER_ERRORS); + + return this.logEventStart('starting scan for rendering errors', { + action: Actions.GET_RENDER_ERRORS, + }); } /** @@ -314,7 +327,8 @@ export class EventLogger { */ public getRenderErrorsEnd({ renderErrors }: { renderErrors?: number }) { this.spans.getRenderErrors?.end(); - this.logEventEnd( + + return this.logEventEnd( 'finished scanning for rendering errors', { action: Actions.GET_RENDER_ERRORS, @@ -333,12 +347,13 @@ export class EventLogger { Actions.GET_SCREENSHOT, SpanTypes.READ ); - this.logEventStart('capturing single screenshot', { + this.startTiming(Actions.GET_SCREENSHOT); + + return this.logEventStart('capturing single screenshot', { action: Actions.GET_SCREENSHOT, screenshot_current: current, screenshot_total: total, }); - this.startTiming(Actions.GET_SCREENSHOT); } /** @@ -347,7 +362,8 @@ export class EventLogger { */ public getScreenshotEnd({ byteLength, current, total }: GetScreenshotOptions) { this.spans.getScreenshot?.end(); - this.logEventEnd( + + return this.logEventEnd( 'single screenshot captured', { action: Actions.GET_SCREENSHOT, @@ -364,13 +380,15 @@ export class EventLogger { Actions.GET_TIMERANGE, SpanTypes.READ ); - this.logEventStart('getting time range', { action: Actions.GET_TIMERANGE }); this.startTiming(Actions.GET_TIMERANGE); + + return this.logEventStart('getting time range', { action: Actions.GET_TIMERANGE }); } public getTimeRangeEnd() { this.spans.getTimeRange?.end(); - this.logEventEnd( + + return this.logEventEnd( 'received time range', { action: Actions.GET_TIMERANGE }, this.timings[Actions.GET_TIMERANGE] @@ -382,13 +400,15 @@ export class EventLogger { Actions.INJECT_CSS, SpanTypes.CORRECT ); - this.logEventStart('injecting css', { action: Actions.INJECT_CSS }); this.startTiming(Actions.INJECT_CSS); + + return this.logEventStart('injecting css', { action: Actions.INJECT_CSS }); } public injectCssEnd() { this.spans.injectCss?.end(); - this.logEventEnd( + + return this.logEventEnd( 'finished injecting css', { action: Actions.INJECT_CSS }, this.timings[Actions.INJECT_CSS] @@ -400,13 +420,15 @@ export class EventLogger { Actions.OPEN_URL, SpanTypes.WAIT ); - this.logEventStart('opening url', { action: Actions.OPEN_URL }); this.startTiming(Actions.OPEN_URL); + + return this.logEventStart('opening url', { action: Actions.OPEN_URL }); } public openUrlEnd() { this.spans.openUrl?.end(); - this.logEventEnd( + + return this.logEventEnd( 'finished opening url', { action: Actions.OPEN_URL }, this.timings[Actions.OPEN_URL] @@ -418,13 +440,15 @@ export class EventLogger { Actions.REPOSITION, SpanTypes.CORRECT ); - this.logEventStart('positioning elements', { action: Actions.REPOSITION }); this.startTiming(Actions.REPOSITION); + + return this.logEventStart('positioning elements', { action: Actions.REPOSITION }); } public positionElementsEnd() { this.spans.positionElements?.end(); - this.logEventEnd( + + return this.logEventEnd( 'finished positioning elements', { action: Actions.REPOSITION }, this.timings[Actions.REPOSITION] @@ -436,13 +460,15 @@ export class EventLogger { Actions.WAIT_RENDER, SpanTypes.WAIT ); - this.logEventStart('waiting for render to complete', { action: Actions.WAIT_RENDER }); this.startTiming(Actions.WAIT_RENDER); + + return this.logEventStart('waiting for render to complete', { action: Actions.WAIT_RENDER }); } public waitForRenderEnd() { this.spans.waitForRender?.end(); - this.logEventEnd( + + return this.logEventEnd( 'finished waiting for render to complete', { action: Actions.WAIT_RENDER }, this.timings[Actions.WAIT_RENDER] @@ -454,13 +480,17 @@ export class EventLogger { Actions.WAIT_VISUALIZATIONS, SpanTypes.WAIT ); - this.logEventStart('waiting for visualizations', { action: Actions.WAIT_VISUALIZATIONS }); this.startTiming(Actions.WAIT_VISUALIZATIONS); + + return this.logEventStart('waiting for visualizations', { + action: Actions.WAIT_VISUALIZATIONS, + }); } public waitForVisualizationEnd() { this.spans.waitForVisualization?.end(); - this.logEventEnd( + + return this.logEventEnd( 'finished waiting for visualizations', { action: Actions.WAIT_VISUALIZATIONS }, this.timings[Actions.WAIT_VISUALIZATIONS] @@ -472,13 +502,15 @@ export class EventLogger { Actions.ADD_IMAGE, SpanTypes.OUTPUT ); - this.logEventStart('adding pdf image', { action: Actions.ADD_IMAGE }); this.startTiming(Actions.ADD_IMAGE); + + return this.logEventStart('adding pdf image', { action: Actions.ADD_IMAGE }); } public addPdfImageEnd() { this.spans.addPdfImage?.end(); - this.logEventEnd( + + return this.logEventEnd( 'pdf image added', { action: Actions.ADD_IMAGE }, this.timings[Actions.ADD_IMAGE] @@ -490,13 +522,15 @@ export class EventLogger { Actions.COMPILE, SpanTypes.OUTPUT ); - this.logEventStart('compiling pdf file', { action: Actions.COMPILE }); this.startTiming(Actions.COMPILE); + + return this.logEventStart('compiling pdf file', { action: Actions.COMPILE }); } public compilePdfEnd() { this.spans.compilePdf?.end(); - this.logEventEnd( + + return this.logEventEnd( 'pdf file compiled', { action: Actions.COMPILE }, this.timings[Actions.COMPILE] @@ -513,9 +547,10 @@ export class EventLogger { public error(error: ErrorAction | string, action: Actions) { const isError = typeof error === 'object'; this.logger.error(error as Error); - this.logger.debug('an error occurred', { + + const logData = { message: 'an error occurred', - kibana: { screenshotting: { action } }, + kibana: { screenshotting: { action: `${action}-error` } }, event: { provider: PLUGIN_ID }, error: { message: isError ? error.message : undefined, @@ -523,6 +558,9 @@ export class EventLogger { stack_trace: isError ? error.stack_trace : undefined, type: isError ? error.type : undefined, }, - }); + }; + this.logger.debug('an error occurred', logData); + + return logData; } } diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts index 8b4ea2ff1347f..c632d69dc7e91 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts @@ -16,50 +16,56 @@ export const waitForRenderComplete = async ( loadDelay: number, layout: Layout ) => { - return await browser.evaluate( - { - fn: (selector, visLoadDelay) => { - // wait for visualizations to finish loading - const visualizations: NodeListOf = document.querySelectorAll(selector); - const visCount = visualizations.length; - const renderedTasks = []; + eventLogger.waitForRenderStart(); - function waitForRender(visualization: Element) { - return new Promise((resolve) => { - visualization.addEventListener('renderComplete', () => resolve()); - }); - } + return await browser + .evaluate( + { + fn: (selector, visLoadDelay) => { + // wait for visualizations to finish loading + const visualizations: NodeListOf = document.querySelectorAll(selector); + const visCount = visualizations.length; + const renderedTasks = []; - function waitForRenderDelay() { - return new Promise((resolve) => { - setTimeout(resolve, visLoadDelay); - }); - } + function waitForRender(visualization: Element) { + return new Promise((resolve) => { + visualization.addEventListener('renderComplete', () => resolve()); + }); + } + + function waitForRenderDelay() { + return new Promise((resolve) => { + setTimeout(resolve, visLoadDelay); + }); + } - for (let i = 0; i < visCount; i++) { - const visualization = visualizations[i]; - const isRendered = visualization.getAttribute('data-render-complete'); + for (let i = 0; i < visCount; i++) { + const visualization = visualizations[i]; + const isRendered = visualization.getAttribute('data-render-complete'); - if (isRendered === 'disabled') { - renderedTasks.push(waitForRenderDelay()); - } else if (isRendered === 'false') { - renderedTasks.push(waitForRender(visualization)); + if (isRendered === 'disabled') { + renderedTasks.push(waitForRenderDelay()); + } else if (isRendered === 'false') { + renderedTasks.push(waitForRender(visualization)); + } } - } - // The renderComplete fires before the visualizations are in the DOM, so - // we wait for the event loop to flush before telling reporting to continue. This - // seems to correct a timing issue that was causing reporting to occasionally - // capture the first visualization before it was actually in the DOM. - // Note: 100 proved too short, see https://github.com/elastic/kibana/issues/22581, - // bumping to 250. - const hackyWaitForVisualizations = () => new Promise((r) => setTimeout(r, 250)); + // The renderComplete fires before the visualizations are in the DOM, so + // we wait for the event loop to flush before telling reporting to continue. This + // seems to correct a timing issue that was causing reporting to occasionally + // capture the first visualization before it was actually in the DOM. + // Note: 100 proved too short, see https://github.com/elastic/kibana/issues/22581, + // bumping to 250. + const hackyWaitForVisualizations = () => new Promise((r) => setTimeout(r, 250)); - return Promise.all(renderedTasks).then(hackyWaitForVisualizations); + return Promise.all(renderedTasks).then(hackyWaitForVisualizations); + }, + args: [layout.selectors.renderComplete, loadDelay], }, - args: [layout.selectors.renderComplete, loadDelay], - }, - { context: CONTEXT_WAITFORRENDER }, - eventLogger.kbnLogger - ); + { context: CONTEXT_WAITFORRENDER }, + eventLogger.kbnLogger + ) + .then(() => { + eventLogger.waitForRenderEnd(); + }); }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts index b78f789a45564..1fbe424ffed94 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts @@ -41,6 +41,8 @@ export const waitForVisualizations = async ( toEqual: number, layout: Layout ): Promise => { + eventLogger.waitForVisualizationStart(); + const logger = eventLogger.kbnLogger; const { renderComplete: renderCompleteSelector } = layout.selectors; @@ -60,4 +62,6 @@ export const waitForVisualizations = async ( `An error occurred when trying to wait for ${toEqual} visualizations to finish rendering. ${err.message}` ); } + + eventLogger.waitForVisualizationEnd(); }; From da7ff566757048320b0470ca818e8c1402468c7a Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Mon, 18 Apr 2022 12:41:07 -0700 Subject: [PATCH 06/28] fix getTimeRangeEnd --- .../server/screenshots/get_number_of_items.ts | 5 ++--- .../screenshotting/server/screenshots/get_time_range.ts | 9 ++++++--- .../server/screenshots/wait_for_visualizations.ts | 2 +- 3 files changed, 9 insertions(+), 7 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts index 01e60a3b82c3b..b6cb22263f87f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts @@ -22,7 +22,6 @@ export const getNumberOfItems = async ( let itemsCount: number; try { - const logger = eventLogger.kbnLogger; // the dashboard is using the `itemsCountAttribute` attribute to let us // know how many items to expect since gridster incrementally adds panels // we have to use this hint to wait for all of them @@ -30,7 +29,7 @@ export const getNumberOfItems = async ( `${renderCompleteSelector},[${itemsCountAttribute}]`, { timeout }, { context: CONTEXT_READMETADATA }, - logger + eventLogger.kbnLogger ); // returns the value of the `itemsCountAttribute` if it's there, otherwise @@ -51,7 +50,7 @@ export const getNumberOfItems = async ( args: [renderCompleteSelector, itemsCountAttribute], }, { context: CONTEXT_GETNUMBEROFITEMS }, - logger + eventLogger.kbnLogger ); } catch (error) { eventLogger.error(error, Actions.GET_NUMBER_OF_ITEMS); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts index 9daff0f26d67c..e0125d3fcbc9f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts @@ -15,7 +15,8 @@ export const getTimeRange = async ( eventLogger: EventLogger, layout: Layout ): Promise => { - const logger = eventLogger.kbnLogger; + eventLogger.getTimeRangeStart(); + const timeRange = await browser.evaluate( { fn: (durationAttribute) => { @@ -35,12 +36,14 @@ export const getTimeRange = async ( args: [layout.selectors.timefilterDurationAttribute], }, { context: CONTEXT_GETTIMERANGE }, - logger + eventLogger.kbnLogger ); if (timeRange) { - logger.info(`timeRange: ${timeRange}`); + eventLogger.kbnLogger.info(`timeRange: ${timeRange}`); } + eventLogger.getTimeRangeEnd(); + return timeRange; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts index 1fbe424ffed94..416e4e8d19660 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts @@ -43,9 +43,9 @@ export const waitForVisualizations = async ( ): Promise => { eventLogger.waitForVisualizationStart(); - const logger = eventLogger.kbnLogger; const { renderComplete: renderCompleteSelector } = layout.selectors; + const logger = eventLogger.kbnLogger; logger.debug(`waiting for ${toEqual} rendered elements to be in the DOM`); try { From e9ade666b3896b8d6661e166d6bf41e7bd6a07d8 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Mon, 18 Apr 2022 12:50:19 -0700 Subject: [PATCH 07/28] improve logging of thrown errors --- .../server/screenshots/get_number_of_items.ts | 5 ++-- .../server/screenshots/observable.ts | 28 +++++++++++++------ .../server/screenshots/open_url.ts | 7 +++-- .../screenshots/wait_for_visualizations.ts | 5 ++-- 4 files changed, 30 insertions(+), 15 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts index b6cb22263f87f..d22dd55b9e31a 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts @@ -53,10 +53,11 @@ export const getNumberOfItems = async ( eventLogger.kbnLogger ); } catch (error) { - eventLogger.error(error, Actions.GET_NUMBER_OF_ITEMS); - throw new Error( + const newError = new Error( `An error occurred when trying to read the page for visualization panel info: ${error.message}` ); + eventLogger.error(newError, Actions.GET_NUMBER_OF_ITEMS); + throw newError; } eventLogger.getNumberOfItemsEnd({ itemsCount }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index fd84a9af30af2..f67ac5f2c9324 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -185,25 +185,34 @@ export class ScreenshotObservableHandler { private completeRender() { const driver = this.driver; const layout = this.layout; - const logger = this.eventLogger; + const eventLogger = this.eventLogger; return defer(async () => { // Waiting till _after_ elements have rendered before injecting our CSS // allows for them to be displayed properly in many cases - await injectCustomCss(driver, logger, layout); + await injectCustomCss(driver, eventLogger, layout); this.eventLogger.positionElementsStart(); // position panel elements for print layout - await layout.positionElements?.(driver, logger.kbnLogger); + await layout.positionElements?.(driver, eventLogger.kbnLogger); this.eventLogger.positionElementsEnd(); - await waitForRenderComplete(driver, logger, toNumber(this.config.capture.loadDelay), layout); + await waitForRenderComplete( + driver, + eventLogger, + toNumber(this.config.capture.loadDelay), + layout + ); }).pipe( mergeMap(() => forkJoin({ - timeRange: getTimeRange(driver, logger, layout), - elementsPositionAndAttributes: getElementPositionAndAttributes(driver, logger, layout), - renderErrors: getRenderErrors(driver, logger, layout), + timeRange: getTimeRange(driver, eventLogger, layout), + elementsPositionAndAttributes: getElementPositionAndAttributes( + driver, + eventLogger, + layout + ), + renderErrors: getRenderErrors(driver, eventLogger, layout), }) ), this.waitUntil(toNumber(this.config.capture.timeouts.renderComplete), 'render complete') @@ -229,8 +238,9 @@ export class ScreenshotObservableHandler { try { screenshots = await getScreenshots(this.driver, this.eventLogger, elements); } catch (e) { - this.eventLogger.error(e, Actions.GET_SCREENSHOT); - throw new errors.FailedToCaptureScreenshot(e.message); + const newError = new errors.FailedToCaptureScreenshot(e.message); + this.eventLogger.error(newError, Actions.GET_SCREENSHOT); + throw newError; } const { timeRange, error: setupError, renderErrors } = data; diff --git a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts index ee1a4cf462576..870681c52ec26 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts @@ -29,8 +29,11 @@ export const openUrl = async ( try { await browser.open(url, { context, headers, waitForSelector, timeout }, eventLogger.kbnLogger); } catch (err) { - eventLogger.error(err, Actions.OPEN_URL); - throw new Error(`An error occurred when trying to open the Kibana URL: ${err.message}`); + const newError = new Error( + `An error occurred when trying to open the Kibana URL: ${err.message}` + ); + eventLogger.error(newError, Actions.OPEN_URL); + throw newError; } eventLogger.openUrlEnd(); diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts index 416e4e8d19660..9761f54eabba4 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts @@ -57,10 +57,11 @@ export const waitForVisualizations = async ( logger.debug(`found ${toEqual} rendered elements in the DOM`); } catch (err) { - eventLogger.error(err, Actions.WAIT_VISUALIZATIONS); - throw new Error( + const newError = new Error( `An error occurred when trying to wait for ${toEqual} visualizations to finish rendering. ${err.message}` ); + eventLogger.error(newError, Actions.WAIT_VISUALIZATIONS); + throw newError; } eventLogger.waitForVisualizationEnd(); From 1f4e9b9621e1b1591cbe0babc97598a048b1eb82 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Mon, 18 Apr 2022 14:06:09 -0700 Subject: [PATCH 08/28] log the number of pixels using zoom --- .../__snapshots__/index.test.ts.snap | 3 + .../screenshots/event_logger/index.test.ts | 75 ++++++++++++++----- .../server/screenshots/event_logger/index.ts | 21 +++++- .../get_element_position_data.test.ts | 2 + .../screenshots/get_element_position_data.ts | 2 + .../screenshots/get_screenshots.test.ts | 2 + .../server/screenshots/get_screenshots.ts | 13 +++- .../server/screenshots/observable.ts | 8 +- 8 files changed, 101 insertions(+), 25 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap b/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap index c0971c9b95763..13c6cde266088 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap +++ b/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap @@ -17,6 +17,7 @@ Array [ "x": 0, "y": 0, }, + "zoom": 2, }, }, ], @@ -60,6 +61,7 @@ Array [ "x": 0, "y": 0, }, + "zoom": 2, }, }, ], @@ -108,6 +110,7 @@ Array [ "x": 0, "y": 0, }, + "zoom": 2, }, }, ], diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index 79536777d8495..d0749df53cf28 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -8,15 +8,16 @@ import moment from 'moment'; import { loggingSystemMock } from '@kbn/core/server/mocks'; import { Actions, EventLogger } from '.'; +import { ElementPosition } from '../get_element_position_data'; describe('Event Logger', () => { let eventLogger: EventLogger; beforeEach(() => { const testDate = moment(new Date('2021-04-12T16:00:00.000Z')); - let walker = 1; + let delaySeconds = 1; jest.spyOn(global.Date, 'now').mockImplementation(() => { - return testDate.add(walker++, 'seconds').valueOf(); + return testDate.add(delaySeconds++, 'seconds').valueOf(); }); eventLogger = new EventLogger(loggingSystemMock.createLogger()); @@ -42,8 +43,6 @@ describe('Event Logger', () => { logs.push(eventLogger.positionElementsEnd()); logs.push(eventLogger.waitForRenderStart()); logs.push(eventLogger.waitForRenderEnd()); - logs.push(eventLogger.getScreenshotStart({ current: 1, total: 1 })); - logs.push(eventLogger.getScreenshotEnd({ byteLength: 4444, current: 1, total: 1 })); logs.push(eventLogger.pdfStart()); logs.push(eventLogger.addPdfImageStart()); logs.push(eventLogger.addPdfImageEnd()); @@ -51,11 +50,11 @@ describe('Event Logger', () => { logs.push(eventLogger.compilePdfEnd()); logs.push(eventLogger.pdfEnd({ pdfPages: 1, byteLengthPdf: 6666 })); - const actionNames = logs.map((log) => ({ + const logData = logs.map((log) => ({ event: log.kibana.screenshotting.action, duration: log.event?.duration, })); - expect(actionNames).toMatchInlineSnapshot(` + expect(logData).toMatchInlineSnapshot(` Array [ Object { "duration": undefined, @@ -125,14 +124,6 @@ describe('Event Logger', () => { "duration": 17000, "event": "wait-for-render-complete", }, - Object { - "duration": undefined, - "event": "get-screenshots-start", - }, - Object { - "duration": 19000, - "event": "get-screenshots-complete", - }, Object { "duration": undefined, "event": "generate-pdf-start", @@ -142,7 +133,7 @@ describe('Event Logger', () => { "event": "add-pdf-image-start", }, Object { - "duration": 22000, + "duration": 20000, "event": "add-pdf-image-complete", }, Object { @@ -150,28 +141,74 @@ describe('Event Logger', () => { "event": "compile-pdf-start", }, Object { - "duration": 24000, + "duration": 22000, "event": "compile-pdf-complete", }, Object { - "duration": 115000, + "duration": 105000, "event": "generate-pdf-complete", }, ] `); }); + it('logs number of pixels', () => { + const logs = []; + const elementPosition = { + zoom: 2, + boundingClientRect: { width: 1350, height: 2000 }, + scroll: {}, + } as ElementPosition; + logs.push(eventLogger.getScreenshotStart({ current: 1, total: 1, elementPosition })); + logs.push( + eventLogger.getScreenshotEnd({ byteLength: 4444, current: 1, total: 1, elementPosition }) + ); + + const logData = logs.map((log) => ({ + message: log.message, + duration: log.event?.duration, + screenshotting: log.kibana.screenshotting, + })); + + expect( + logData.map((l) => ({ + duration: l.duration, + message: l.message, + action: l.screenshotting.action, + byte_length: l.screenshotting.byte_length, + pixels: l.screenshotting.pixels, + })) + ).toMatchInlineSnapshot(` + Array [ + Object { + "action": "get-screenshots-start", + "byte_length": undefined, + "duration": undefined, + "message": "capturing single screenshot", + "pixels": 10800000, + }, + Object { + "action": "get-screenshots-complete", + "byte_length": 4444, + "duration": 2000, + "message": "single screenshot captured", + "pixels": 10800000, + }, + ] + `); + }); + it('creates helpful error logs', () => { const logs = []; logs.push(eventLogger.screenshottingStart()); logs.push(eventLogger.error(new Error('Something erroneous happened'), Actions.SCREENSHOTTING)); - const actionNames = logs.map((log) => ({ + const logData = logs.map((log) => ({ action: log.kibana.screenshotting.action, message: log.message, error: log.error, })); - expect(actionNames).toMatchInlineSnapshot(` + expect(logData).toMatchInlineSnapshot(` Array [ Object { "action": "screenshot-pipeline-start", diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index ed24c18c7b1f8..1ed9cc3470fec 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -11,6 +11,7 @@ import { Logger, LogMeta } from '@kbn/core/server'; import { CaptureResult } from '..'; import { PLUGIN_ID } from '../../../common'; import { Screenshot } from '../get_screenshots'; +import { ElementPosition } from '../get_element_position_data'; export enum Actions { SCREENSHOTTING = 'screenshot-pipeline', @@ -57,6 +58,7 @@ export interface ScreenshottingAction extends LogMeta { // screenshotting stats items_count?: number; + pixels?: number; byte_length?: number; element_positions?: number; screenshot_current?: number; @@ -80,6 +82,7 @@ interface ErrorAction { interface GetScreenshotOptions { current: number; // current screenshot to be taken total: number; // total number of screenshots to be taken + elementPosition: ElementPosition; byteLength?: number; // byte length of completed completed current screenshot } @@ -338,11 +341,18 @@ export class EventLogger { ); } + private getPixels(elementPosition: ElementPosition) { + const { width, height } = elementPosition.boundingClientRect; + const { zoom } = elementPosition; + + return width * zoom * (height * zoom); + } + /** * @param GetScreenshotOptions - context of the screenshot to be taken * @returns void */ - public getScreenshotStart({ current, total }: GetScreenshotOptions) { + public getScreenshotStart({ current, total, elementPosition }: GetScreenshotOptions) { this.spans.getScreenshot = this.transactions.screenshotting?.startSpan( Actions.GET_SCREENSHOT, SpanTypes.READ @@ -353,6 +363,7 @@ export class EventLogger { action: Actions.GET_SCREENSHOT, screenshot_current: current, screenshot_total: total, + pixels: this.getPixels(elementPosition), }); } @@ -360,7 +371,12 @@ export class EventLogger { * @param GetScreenshotOptions - context of the screenshot taken * @returns void */ - public getScreenshotEnd({ byteLength, current, total }: GetScreenshotOptions) { + public getScreenshotEnd({ + byteLength, + current, + total, + elementPosition, + }: Required) { this.spans.getScreenshot?.end(); return this.logEventEnd( @@ -370,6 +386,7 @@ export class EventLogger { byte_length: byteLength, screenshot_current: current, screenshot_total: total, + pixels: this.getPixels(elementPosition), }, this.timings[Actions.GET_SCREENSHOT] ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts index 6b3db8628cffb..948197a48f17d 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts @@ -79,6 +79,7 @@ describe('getElementPositionAndAttributes', () => { "x": 0, "y": 0, }, + "zoom": 2, }, }, Object { @@ -97,6 +98,7 @@ describe('getElementPositionAndAttributes', () => { "x": 0, "y": 0, }, + "zoom": 2, }, }, ] diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index d4da179d3b1ee..b1feb4975a434 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -26,6 +26,7 @@ export interface ElementPosition { x: number; y: number; }; + zoom: number; } export interface ElementsPositionAndAttribute { @@ -64,6 +65,7 @@ export const getElementPositionAndAttributes = async ( x: window.scrollX, y: window.scrollY, }, + zoom: layout.getBrowserZoom(), }, attributes: Object.keys(attributes).reduce((result: AttributesMap, key) => { const attribute = attributes[key]; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts index 8313d7116ee71..5d5ded734865b 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts @@ -18,6 +18,7 @@ describe('getScreenshots', () => { boundingClientRect: { top: 10, left: 10, height: 100, width: 100 }, scroll: { x: 100, y: 100 }, }, + zoom: 2, }, { attributes: { description: 'description2', title: 'title2' }, @@ -25,6 +26,7 @@ describe('getScreenshots', () => { boundingClientRect: { top: 10, left: 10, height: 100, width: 100 }, scroll: { x: 100, y: 100 }, }, + zoom: 2, }, ]; let browser: ReturnType; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index b2bb5e7814493..58af54f61c2ef 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -38,8 +38,12 @@ export const getScreenshots = async ( const size = elementsPositionAndAttributes.length; for (let i = 0; i < size; i++) { - eventLogger.getScreenshotStart({ current: size, total: i + 1 }); const item = elementsPositionAndAttributes[i]; + eventLogger.getScreenshotStart({ + current: size, + total: i + 1, + elementPosition: item.position, + }); const data = await browser.screenshot(item.position); @@ -53,7 +57,12 @@ export const getScreenshots = async ( description: item.attributes.description, }); - eventLogger.getScreenshotEnd({ byteLength: data.byteLength, current: size, total: i + 1 }); + eventLogger.getScreenshotEnd({ + current: size, + total: i + 1, + elementPosition: item.position, + byteLength: data.byteLength, + }); } kbnLogger.info(`screenshots taken: ${screenshots.length}`); diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index f67ac5f2c9324..5ea8b9fee08b8 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -90,7 +90,10 @@ interface PageSetupResults { renderErrors?: string[]; } -const getDefaultElementPosition = (dimensions: { height?: number; width?: number } | null) => { +const getDefaultElementPosition = ( + dimensions: { height?: number; width?: number } | null, + config: ConfigType +): ElementsPositionAndAttribute[] => { const height = dimensions?.height || DEFAULT_VIEWPORT.height; const width = dimensions?.width || DEFAULT_VIEWPORT.width; @@ -99,6 +102,7 @@ const getDefaultElementPosition = (dimensions: { height?: number; width?: number position: { boundingClientRect: { top: 0, left: 0, height, width }, scroll: { x: 0, y: 0 }, + zoom: config.capture.zoom, }, attributes: {}, }, @@ -233,7 +237,7 @@ export class ScreenshotObservableHandler { this.checkPageIsOpen(); // fail the report job if the browser has closed const elements = data.elementsPositionAndAttributes ?? - getDefaultElementPosition(this.layout.getViewport(1)); + getDefaultElementPosition(this.layout.getViewport(1), this.config); let screenshots: Screenshot[] = []; try { screenshots = await getScreenshots(this.driver, this.eventLogger, elements); From 58499599db184f5020d42d2f2ba95d76aadadcfd Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Tue, 19 Apr 2022 17:03:11 -0700 Subject: [PATCH 09/28] use elementPositionAndAttributes for logging --- .../__snapshots__/index.test.ts.snap | 6 ++--- .../screenshots/event_logger/index.test.ts | 23 +++++++++++++------ .../server/screenshots/event_logger/index.ts | 18 +++++++-------- .../get_element_position_data.test.ts | 4 ++-- .../screenshots/get_element_position_data.ts | 4 ++-- .../server/screenshots/get_screenshots.ts | 4 ++-- .../server/screenshots/observable.ts | 2 +- 7 files changed, 35 insertions(+), 26 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap b/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap index 13c6cde266088..b4eecc38aa646 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap +++ b/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap @@ -17,8 +17,8 @@ Array [ "x": 0, "y": 0, }, - "zoom": 2, }, + "zoom": 2, }, ], "error": [Error: The "wait for elements" phase encountered an error: Error: An error occurred when trying to read the page for visualization panel info: Mock error!], @@ -61,8 +61,8 @@ Array [ "x": 0, "y": 0, }, - "zoom": 2, }, + "zoom": 2, }, ], "error": [Error: The "wait for elements" phase encountered an error: Error: An error occurred when trying to read the page for visualization panel info: Mock error!], @@ -110,8 +110,8 @@ Array [ "x": 0, "y": 0, }, - "zoom": 2, }, + "zoom": 2, }, ], "error": undefined, diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index d0749df53cf28..6ed614c41d1cb 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -8,7 +8,7 @@ import moment from 'moment'; import { loggingSystemMock } from '@kbn/core/server/mocks'; import { Actions, EventLogger } from '.'; -import { ElementPosition } from '../get_element_position_data'; +import { ElementsPositionAndAttribute } from '../get_element_position_data'; describe('Event Logger', () => { let eventLogger: EventLogger; @@ -154,14 +154,23 @@ describe('Event Logger', () => { it('logs number of pixels', () => { const logs = []; - const elementPosition = { + const elementPositionAndAttribute = { + position: { + boundingClientRect: { width: 1350, height: 2000 }, + scroll: {}, + }, zoom: 2, - boundingClientRect: { width: 1350, height: 2000 }, - scroll: {}, - } as ElementPosition; - logs.push(eventLogger.getScreenshotStart({ current: 1, total: 1, elementPosition })); + } as ElementsPositionAndAttribute; logs.push( - eventLogger.getScreenshotEnd({ byteLength: 4444, current: 1, total: 1, elementPosition }) + eventLogger.getScreenshotStart({ current: 1, total: 1, elementPositionAndAttribute }) + ); + logs.push( + eventLogger.getScreenshotEnd({ + byteLength: 4444, + current: 1, + total: 1, + elementPositionAndAttribute, + }) ); const logData = logs.map((log) => ({ diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 1ed9cc3470fec..89ce5cd50d6d0 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -11,7 +11,7 @@ import { Logger, LogMeta } from '@kbn/core/server'; import { CaptureResult } from '..'; import { PLUGIN_ID } from '../../../common'; import { Screenshot } from '../get_screenshots'; -import { ElementPosition } from '../get_element_position_data'; +import { ElementsPositionAndAttribute } from '../get_element_position_data'; export enum Actions { SCREENSHOTTING = 'screenshot-pipeline', @@ -82,7 +82,7 @@ interface ErrorAction { interface GetScreenshotOptions { current: number; // current screenshot to be taken total: number; // total number of screenshots to be taken - elementPosition: ElementPosition; + elementPositionAndAttribute: ElementsPositionAndAttribute; byteLength?: number; // byte length of completed completed current screenshot } @@ -341,9 +341,9 @@ export class EventLogger { ); } - private getPixels(elementPosition: ElementPosition) { - const { width, height } = elementPosition.boundingClientRect; - const { zoom } = elementPosition; + private getPixels(elementPositionAndAttribute: ElementsPositionAndAttribute) { + const { width, height } = elementPositionAndAttribute.position.boundingClientRect; + const { zoom } = elementPositionAndAttribute; return width * zoom * (height * zoom); } @@ -352,7 +352,7 @@ export class EventLogger { * @param GetScreenshotOptions - context of the screenshot to be taken * @returns void */ - public getScreenshotStart({ current, total, elementPosition }: GetScreenshotOptions) { + public getScreenshotStart({ current, total, elementPositionAndAttribute }: GetScreenshotOptions) { this.spans.getScreenshot = this.transactions.screenshotting?.startSpan( Actions.GET_SCREENSHOT, SpanTypes.READ @@ -363,7 +363,7 @@ export class EventLogger { action: Actions.GET_SCREENSHOT, screenshot_current: current, screenshot_total: total, - pixels: this.getPixels(elementPosition), + pixels: this.getPixels(elementPositionAndAttribute), }); } @@ -375,7 +375,7 @@ export class EventLogger { byteLength, current, total, - elementPosition, + elementPositionAndAttribute, }: Required) { this.spans.getScreenshot?.end(); @@ -386,7 +386,7 @@ export class EventLogger { byte_length: byteLength, screenshot_current: current, screenshot_total: total, - pixels: this.getPixels(elementPosition), + pixels: this.getPixels(elementPositionAndAttribute), }, this.timings[Actions.GET_SCREENSHOT] ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts index 948197a48f17d..48834874e93f3 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts @@ -79,8 +79,8 @@ describe('getElementPositionAndAttributes', () => { "x": 0, "y": 0, }, - "zoom": 2, }, + "zoom": 2, }, Object { "attributes": Object { @@ -98,8 +98,8 @@ describe('getElementPositionAndAttributes', () => { "x": 0, "y": 0, }, - "zoom": 2, }, + "zoom": 2, }, ] `); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index b1feb4975a434..432aa0fdbc4bf 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -26,12 +26,12 @@ export interface ElementPosition { x: number; y: number; }; - zoom: number; } export interface ElementsPositionAndAttribute { position: ElementPosition; attributes: AttributesMap; + zoom: number; } export const getElementPositionAndAttributes = async ( @@ -65,13 +65,13 @@ export const getElementPositionAndAttributes = async ( x: window.scrollX, y: window.scrollY, }, - zoom: layout.getBrowserZoom(), }, attributes: Object.keys(attributes).reduce((result: AttributesMap, key) => { const attribute = attributes[key]; result[key] = element.getAttribute(attribute); return result; }, {} as AttributesMap), + zoom: layout.getBrowserZoom(), }); } return results; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index 58af54f61c2ef..0b164b27353e9 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -42,7 +42,7 @@ export const getScreenshots = async ( eventLogger.getScreenshotStart({ current: size, total: i + 1, - elementPosition: item.position, + elementPositionAndAttribute: item, }); const data = await browser.screenshot(item.position); @@ -60,7 +60,7 @@ export const getScreenshots = async ( eventLogger.getScreenshotEnd({ current: size, total: i + 1, - elementPosition: item.position, + elementPositionAndAttribute: item, byteLength: data.byteLength, }); } diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index 5ea8b9fee08b8..e6b31230b56c6 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -102,9 +102,9 @@ const getDefaultElementPosition = ( position: { boundingClientRect: { top: 0, left: 0, height, width }, scroll: { x: 0, y: 0 }, - zoom: config.capture.zoom, }, attributes: {}, + zoom: config.capture.zoom, }, ]; }; From 8d66a62925af008eeb29ef6ea0542e4cdc0de8f9 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Tue, 19 Apr 2022 17:25:49 -0700 Subject: [PATCH 10/28] fix tests --- .../__snapshots__/index.test.ts.snap | 3 -- .../screenshots/event_logger/index.test.ts | 32 ++++++---------- .../server/screenshots/event_logger/index.ts | 38 ++++++------------- .../get_element_position_data.test.ts | 7 ++-- .../screenshots/get_element_position_data.ts | 2 - .../screenshots/get_number_of_items.test.ts | 5 ++- .../screenshots/get_render_errors.test.ts | 5 ++- .../screenshots/get_screenshots.test.ts | 7 ++-- .../server/screenshots/get_screenshots.ts | 11 ++---- .../server/screenshots/get_time_range.test.ts | 5 ++- .../server/screenshots/index.ts | 8 ++-- .../server/screenshots/observable.test.ts | 8 +--- .../server/screenshots/observable.ts | 6 +-- 13 files changed, 55 insertions(+), 82 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap b/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap index b4eecc38aa646..c0971c9b95763 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap +++ b/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap @@ -18,7 +18,6 @@ Array [ "y": 0, }, }, - "zoom": 2, }, ], "error": [Error: The "wait for elements" phase encountered an error: Error: An error occurred when trying to read the page for visualization panel info: Mock error!], @@ -62,7 +61,6 @@ Array [ "y": 0, }, }, - "zoom": 2, }, ], "error": [Error: The "wait for elements" phase encountered an error: Error: An error occurred when trying to read the page for visualization panel info: Mock error!], @@ -111,7 +109,6 @@ Array [ "y": 0, }, }, - "zoom": 2, }, ], "error": undefined, diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index 6ed614c41d1cb..912bbc7245b3d 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -8,10 +8,12 @@ import moment from 'moment'; import { loggingSystemMock } from '@kbn/core/server/mocks'; import { Actions, EventLogger } from '.'; -import { ElementsPositionAndAttribute } from '../get_element_position_data'; +import { ElementPosition } from '../get_element_position_data'; +import { ConfigType } from '../../config'; describe('Event Logger', () => { let eventLogger: EventLogger; + let config: ConfigType; beforeEach(() => { const testDate = moment(new Date('2021-04-12T16:00:00.000Z')); @@ -20,7 +22,9 @@ describe('Event Logger', () => { return testDate.add(delaySeconds++, 'seconds').valueOf(); }); - eventLogger = new EventLogger(loggingSystemMock.createLogger()); + config = { capture: { zoom: 2 } } as ConfigType; + + eventLogger = new EventLogger(loggingSystemMock.createLogger(), config); }); it('creates logs for the events and includes durations and event payload data', () => { @@ -154,24 +158,12 @@ describe('Event Logger', () => { it('logs number of pixels', () => { const logs = []; - const elementPositionAndAttribute = { - position: { - boundingClientRect: { width: 1350, height: 2000 }, - scroll: {}, - }, - zoom: 2, - } as ElementsPositionAndAttribute; - logs.push( - eventLogger.getScreenshotStart({ current: 1, total: 1, elementPositionAndAttribute }) - ); - logs.push( - eventLogger.getScreenshotEnd({ - byteLength: 4444, - current: 1, - total: 1, - elementPositionAndAttribute, - }) - ); + const elementPosition = { + boundingClientRect: { width: 1350, height: 2000 }, + scroll: {}, + } as ElementPosition; + logs.push(eventLogger.getScreenshotStart({ elementPosition })); + logs.push(eventLogger.getScreenshotEnd({ byteLength: 4444, elementPosition })); const logData = logs.map((log) => ({ message: log.message, diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 89ce5cd50d6d0..b947853bd5a43 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -5,13 +5,14 @@ * 2.0. */ -import uuid from 'uuid'; -import apm from 'elastic-apm-node'; import { Logger, LogMeta } from '@kbn/core/server'; +import apm from 'elastic-apm-node'; +import uuid from 'uuid'; import { CaptureResult } from '..'; import { PLUGIN_ID } from '../../../common'; +import { ConfigType } from '../../config'; +import { ElementPosition } from '../get_element_position_data'; import { Screenshot } from '../get_screenshots'; -import { ElementsPositionAndAttribute } from '../get_element_position_data'; export enum Actions { SCREENSHOTTING = 'screenshot-pipeline', @@ -61,8 +62,6 @@ export interface ScreenshottingAction extends LogMeta { pixels?: number; byte_length?: number; element_positions?: number; - screenshot_current?: number; - screenshot_total?: number; // should match element_positions render_errors?: number; // pdf stats @@ -80,9 +79,7 @@ interface ErrorAction { } interface GetScreenshotOptions { - current: number; // current screenshot to be taken - total: number; // total number of screenshots to be taken - elementPositionAndAttribute: ElementsPositionAndAttribute; + elementPosition: ElementPosition; byteLength?: number; // byte length of completed completed current screenshot } @@ -167,7 +164,7 @@ export class EventLogger { private logEventEnd: LogAdapter; private timings: Partial> = {}; - constructor(private readonly logger: Logger) { + constructor(private readonly logger: Logger, private readonly config: ConfigType) { this.sessionId = uuid.v4(); this.logEventStart = logAdapter(logger.get('events'), 'start', this.sessionId); this.logEventEnd = logAdapter(logger.get('events'), 'complete', this.sessionId); @@ -341,10 +338,8 @@ export class EventLogger { ); } - private getPixels(elementPositionAndAttribute: ElementsPositionAndAttribute) { - const { width, height } = elementPositionAndAttribute.position.boundingClientRect; - const { zoom } = elementPositionAndAttribute; - + private getPixels(elementPosition: ElementPosition, zoom: number) { + const { width, height } = elementPosition.boundingClientRect; return width * zoom * (height * zoom); } @@ -352,7 +347,7 @@ export class EventLogger { * @param GetScreenshotOptions - context of the screenshot to be taken * @returns void */ - public getScreenshotStart({ current, total, elementPositionAndAttribute }: GetScreenshotOptions) { + public getScreenshotStart({ elementPosition }: GetScreenshotOptions) { this.spans.getScreenshot = this.transactions.screenshotting?.startSpan( Actions.GET_SCREENSHOT, SpanTypes.READ @@ -361,9 +356,7 @@ export class EventLogger { return this.logEventStart('capturing single screenshot', { action: Actions.GET_SCREENSHOT, - screenshot_current: current, - screenshot_total: total, - pixels: this.getPixels(elementPositionAndAttribute), + pixels: this.getPixels(elementPosition, this.config.capture.zoom), }); } @@ -371,12 +364,7 @@ export class EventLogger { * @param GetScreenshotOptions - context of the screenshot taken * @returns void */ - public getScreenshotEnd({ - byteLength, - current, - total, - elementPositionAndAttribute, - }: Required) { + public getScreenshotEnd({ byteLength, elementPosition }: Required) { this.spans.getScreenshot?.end(); return this.logEventEnd( @@ -384,9 +372,7 @@ export class EventLogger { { action: Actions.GET_SCREENSHOT, byte_length: byteLength, - screenshot_current: current, - screenshot_total: total, - pixels: this.getPixels(elementPositionAndAttribute), + pixels: this.getPixels(elementPosition, this.config.capture.zoom), }, this.timings[Actions.GET_SCREENSHOT] ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts index 48834874e93f3..f3a76ca79d85f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.test.ts @@ -7,6 +7,7 @@ import { loggingSystemMock } from '@kbn/core/server/mocks'; import { createMockBrowserDriver } from '../browsers/mock'; +import { ConfigType } from '../config'; import { createMockLayout } from '../layouts/mock'; import { EventLogger } from './event_logger'; import { getElementPositionAndAttributes } from './get_element_position_data'; @@ -15,11 +16,13 @@ describe('getElementPositionAndAttributes', () => { let browser: ReturnType; let layout: ReturnType; let eventLogger: EventLogger; + let config = {} as ConfigType; beforeEach(async () => { browser = createMockBrowserDriver(); layout = createMockLayout(); - eventLogger = new EventLogger(loggingSystemMock.createLogger()); + config = { capture: { zoom: 2 } } as ConfigType; + eventLogger = new EventLogger(loggingSystemMock.createLogger(), config); browser.evaluate.mockImplementation(({ fn, args }) => (fn as Function)(...args)); // @see https://github.com/jsdom/jsdom/issues/653 @@ -80,7 +83,6 @@ describe('getElementPositionAndAttributes', () => { "y": 0, }, }, - "zoom": 2, }, Object { "attributes": Object { @@ -99,7 +101,6 @@ describe('getElementPositionAndAttributes', () => { "y": 0, }, }, - "zoom": 2, }, ] `); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index 432aa0fdbc4bf..d4da179d3b1ee 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -31,7 +31,6 @@ export interface ElementPosition { export interface ElementsPositionAndAttribute { position: ElementPosition; attributes: AttributesMap; - zoom: number; } export const getElementPositionAndAttributes = async ( @@ -71,7 +70,6 @@ export const getElementPositionAndAttributes = async ( result[key] = element.getAttribute(attribute); return result; }, {} as AttributesMap), - zoom: layout.getBrowserZoom(), }); } return results; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.test.ts index 5aa0a75ab206e..a7c4f27065bcf 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.test.ts @@ -7,6 +7,7 @@ import { loggingSystemMock } from '@kbn/core/server/mocks'; import { createMockBrowserDriver } from '../browsers/mock'; +import { ConfigType } from '../config'; import { createMockLayout } from '../layouts/mock'; import { EventLogger } from './event_logger'; import { getNumberOfItems } from './get_number_of_items'; @@ -16,11 +17,13 @@ describe('getNumberOfItems', () => { let browser: ReturnType; let layout: ReturnType; let eventLogger: EventLogger; + let config = {} as ConfigType; beforeEach(async () => { browser = createMockBrowserDriver(); layout = createMockLayout(); - eventLogger = new EventLogger(loggingSystemMock.createLogger()); + config = { capture: { zoom: 2 } } as ConfigType; + eventLogger = new EventLogger(loggingSystemMock.createLogger(), config); browser.evaluate.mockImplementation(({ fn, args }) => (fn as Function)(...args)); }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.test.ts index e2ffa8faf6e9f..ece25b37725c8 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.test.ts @@ -7,6 +7,7 @@ import { loggingSystemMock } from '@kbn/core/server/mocks'; import { createMockBrowserDriver } from '../browsers/mock'; +import { ConfigType } from '../config'; import { createMockLayout } from '../layouts/mock'; import { EventLogger } from './event_logger'; import { getRenderErrors } from './get_render_errors'; @@ -15,11 +16,13 @@ describe('getRenderErrors', () => { let browser: ReturnType; let layout: ReturnType; let eventLogger: EventLogger; + let config = {} as ConfigType; beforeEach(async () => { browser = createMockBrowserDriver(); layout = createMockLayout(); - eventLogger = new EventLogger(loggingSystemMock.createLogger()); + config = { capture: { zoom: 2 } } as ConfigType; + eventLogger = new EventLogger(loggingSystemMock.createLogger(), config); browser.evaluate.mockImplementation(({ fn, args }) => (fn as Function)(...args)); }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts index 5d5ded734865b..c2342280aea20 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.test.ts @@ -7,6 +7,7 @@ import { loggingSystemMock } from '@kbn/core/server/mocks'; import { createMockBrowserDriver } from '../browsers/mock'; +import { ConfigType } from '../config'; import { EventLogger } from './event_logger'; import { getScreenshots } from './get_screenshots'; @@ -18,7 +19,6 @@ describe('getScreenshots', () => { boundingClientRect: { top: 10, left: 10, height: 100, width: 100 }, scroll: { x: 100, y: 100 }, }, - zoom: 2, }, { attributes: { description: 'description2', title: 'title2' }, @@ -26,15 +26,16 @@ describe('getScreenshots', () => { boundingClientRect: { top: 10, left: 10, height: 100, width: 100 }, scroll: { x: 100, y: 100 }, }, - zoom: 2, }, ]; let browser: ReturnType; let eventLogger: EventLogger; + let config = {} as ConfigType; beforeEach(async () => { browser = createMockBrowserDriver(); - eventLogger = new EventLogger(loggingSystemMock.createLogger()); + config = { capture: { zoom: 2 } } as ConfigType; + eventLogger = new EventLogger(loggingSystemMock.createLogger(), config); browser.evaluate.mockImplementation(({ fn, args }) => (fn as Function)(...args)); }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index 0b164b27353e9..177b7abc2f7b7 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -36,13 +36,10 @@ export const getScreenshots = async ( const screenshots: Screenshot[] = []; - const size = elementsPositionAndAttributes.length; - for (let i = 0; i < size; i++) { + for (let i = 0; i < elementsPositionAndAttributes.length; i++) { const item = elementsPositionAndAttributes[i]; eventLogger.getScreenshotStart({ - current: size, - total: i + 1, - elementPositionAndAttribute: item, + elementPosition: item.position, }); const data = await browser.screenshot(item.position); @@ -58,9 +55,7 @@ export const getScreenshots = async ( }); eventLogger.getScreenshotEnd({ - current: size, - total: i + 1, - elementPositionAndAttribute: item, + elementPosition: item.position, byteLength: data.byteLength, }); } diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.test.ts b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.test.ts index ed647e093e67e..a7a7b9295068e 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.test.ts @@ -7,6 +7,7 @@ import { loggingSystemMock } from '@kbn/core/server/mocks'; import { createMockBrowserDriver } from '../browsers/mock'; +import { ConfigType } from '../config'; import { createMockLayout } from '../layouts/mock'; import { EventLogger } from './event_logger'; import { getTimeRange } from './get_time_range'; @@ -15,11 +16,13 @@ describe('getTimeRange', () => { let browser: ReturnType; let layout: ReturnType; let eventLogger: EventLogger; + let config = {} as ConfigType; beforeEach(async () => { browser = createMockBrowserDriver(); layout = createMockLayout(); - eventLogger = new EventLogger(loggingSystemMock.createLogger()); + config = { capture: { zoom: 2 } } as ConfigType; + eventLogger = new EventLogger(loggingSystemMock.createLogger(), config); browser.evaluate.mockImplementation(({ fn, args }) => (fn as Function)(...args)); }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/index.ts b/x-pack/plugins/screenshotting/server/screenshots/index.ts index aa9540632f829..84e7a9c5b96ac 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/index.ts @@ -113,9 +113,9 @@ export class Screenshots { } private captureScreenshots( + eventLogger: EventLogger, layout: Layout, - options: ScreenshotObservableOptions, - eventLogger: EventLogger + options: ScreenshotObservableOptions ): Observable { const { browserTimezone } = options; @@ -217,13 +217,13 @@ export class Screenshots { getScreenshots(options: PdfScreenshotOptions): Observable; getScreenshots(options: ScreenshotOptions): Observable; getScreenshots(options: ScreenshotOptions): Observable { - const eventLogger = new EventLogger(this.logger); + const eventLogger = new EventLogger(this.logger, this.config); eventLogger.screenshottingStart(); const layout = this.createLayout(options); const captureOptions = this.getCaptureOptions(options); - return this.captureScreenshots(layout, captureOptions, eventLogger).pipe( + return this.captureScreenshots(eventLogger, layout, captureOptions).pipe( tap((results) => { eventLogger.screenshottingEnd(results); }), diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.test.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.test.ts index a67aff8334cce..b282cd32bbd80 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.test.ts @@ -25,17 +25,13 @@ describe('ScreenshotObservableHandler', () => { browser = createMockBrowserDriver(); config = { capture: { - timeouts: { - openUrl: 30000, - waitForElements: 30000, - renderComplete: 30000, - }, + timeouts: { openUrl: 30000, waitForElements: 30000, renderComplete: 30000 }, loadDelay: 5000, zoom: 13, }, } as ConfigType; layout = createMockLayout(); - eventLogger = new EventLogger(loggingSystemMock.createLogger()); + eventLogger = new EventLogger(loggingSystemMock.createLogger(), config); options = { headers: { testHeader: 'testHeadValue' }, urls: [], diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index e6b31230b56c6..d58ae28b3daeb 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -91,8 +91,7 @@ interface PageSetupResults { } const getDefaultElementPosition = ( - dimensions: { height?: number; width?: number } | null, - config: ConfigType + dimensions: { height?: number; width?: number } | null ): ElementsPositionAndAttribute[] => { const height = dimensions?.height || DEFAULT_VIEWPORT.height; const width = dimensions?.width || DEFAULT_VIEWPORT.width; @@ -104,7 +103,6 @@ const getDefaultElementPosition = ( scroll: { x: 0, y: 0 }, }, attributes: {}, - zoom: config.capture.zoom, }, ]; }; @@ -237,7 +235,7 @@ export class ScreenshotObservableHandler { this.checkPageIsOpen(); // fail the report job if the browser has closed const elements = data.elementsPositionAndAttributes ?? - getDefaultElementPosition(this.layout.getViewport(1), this.config); + getDefaultElementPosition(this.layout.getViewport(1)); let screenshots: Screenshot[] = []; try { screenshots = await getScreenshots(this.driver, this.eventLogger, elements); From 102b985ee1515aee0ccf861430bd6d083ab19123 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 12:06:52 -0700 Subject: [PATCH 11/28] replace multiple methods for logging spans with single log method --- .../server/formats/pdf/pdf_maker/index.ts | 19 +- .../screenshots/event_logger/index.test.ts | 207 ++++---- .../server/screenshots/event_logger/index.ts | 461 +++--------------- .../screenshots/get_element_position_data.ts | 9 +- .../server/screenshots/get_number_of_items.ts | 9 +- .../server/screenshots/get_render_errors.ts | 11 +- .../server/screenshots/get_screenshots.ts | 4 +- .../server/screenshots/get_time_range.ts | 11 +- .../server/screenshots/index.ts | 4 +- .../server/screenshots/inject_css.ts | 9 +- .../server/screenshots/observable.ts | 9 +- .../server/screenshots/open_url.ts | 4 +- .../server/screenshots/wait_for_render.ts | 11 +- .../screenshots/wait_for_visualizations.ts | 9 +- 14 files changed, 243 insertions(+), 534 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts index b9c01ff82c76b..d3b03c836c7ed 100644 --- a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts +++ b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts @@ -8,7 +8,7 @@ import type { PackageInfo } from '@kbn/core/server'; import type { Layout } from '../../../layouts'; import type { CaptureResult } from '../../../screenshots'; -import { EventLogger } from '../../../screenshots/event_logger'; +import { Actions, EventLogger } from '../../../screenshots/event_logger'; import { PdfMaker } from './pdfmaker'; interface PngsToPdfArgs { @@ -28,30 +28,35 @@ export async function pngsToPdf({ packageInfo, eventLogger, }: PngsToPdfArgs): Promise<{ buffer: Buffer; pages: number }> { - eventLogger.pdfStart(); + const transactionEnd = eventLogger.pdfTransaction(); const pdfMaker = new PdfMaker(layout, logo, packageInfo, eventLogger.kbnLogger); if (title) { pdfMaker.setTitle(title); } results.forEach((result) => { result.screenshots.forEach((png) => { - eventLogger.addPdfImageStart(); + const spanEnd = eventLogger.log( + 'add image to PDF file', + Actions.ADD_IMAGE, + 'generatePdf', + 'output' + ); pdfMaker.addImage(png.data, { title: png.title ?? undefined, description: png.description ?? undefined, }); - eventLogger.addPdfImageEnd(); + spanEnd(); }); }); let buffer: Uint8Array | null = null; try { - eventLogger.compilePdfStart(); + const spanEnd = eventLogger.log('compile PDF file', Actions.COMPILE, 'generatePdf', 'output'); buffer = await pdfMaker.generate(); - eventLogger.compilePdfEnd(); + spanEnd(); const byteLength = buffer?.byteLength ?? 0; - eventLogger.pdfEnd({ byteLengthPdf: byteLength, pdfPages: pdfMaker.getPageCount() }); + transactionEnd({ byte_length_pdf: byteLength, pdf_pages: pdfMaker.getPageCount() }); } catch (err) { throw err; } diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index 912bbc7245b3d..427ef2ab36a2c 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -7,214 +7,179 @@ import moment from 'moment'; import { loggingSystemMock } from '@kbn/core/server/mocks'; -import { Actions, EventLogger } from '.'; +import { Actions, EventLogger, ScreenshottingAction } from '.'; import { ElementPosition } from '../get_element_position_data'; import { ConfigType } from '../../config'; +type EventLoggerArgs = [message: string, meta: ScreenshottingAction]; describe('Event Logger', () => { let eventLogger: EventLogger; let config: ConfigType; + let logSpy: jest.SpyInstance; beforeEach(() => { const testDate = moment(new Date('2021-04-12T16:00:00.000Z')); let delaySeconds = 1; + jest.spyOn(global.Date, 'now').mockImplementation(() => { return testDate.add(delaySeconds++, 'seconds').valueOf(); }); + const logger = loggingSystemMock.createLogger(); config = { capture: { zoom: 2 } } as ConfigType; + eventLogger = new EventLogger(logger, config); - eventLogger = new EventLogger(loggingSystemMock.createLogger(), config); + logSpy = jest.spyOn(logger, 'debug') as jest.SpyInstance; }); it('creates logs for the events and includes durations and event payload data', () => { - const logs = []; - logs.push(eventLogger.screenshottingStart()); - logs.push(eventLogger.openUrlStart()); - logs.push(eventLogger.openUrlEnd()); - logs.push(eventLogger.getElementPositionsStart()); - logs.push(eventLogger.getElementPositionsEnd({ elementPositions: 44 })); - - logs.push(eventLogger.getNumberOfItemsStart()); - logs.push(eventLogger.getNumberOfItemsEnd({ itemsCount: 3 })); - logs.push(eventLogger.getRenderErrorsStart()); - logs.push(eventLogger.getRenderErrorsEnd({ renderErrors: 0 })); - logs.push(eventLogger.getTimeRangeStart()); - logs.push(eventLogger.getTimeRangeEnd()); - logs.push(eventLogger.injectCssStart()); - logs.push(eventLogger.injectCssEnd()); - logs.push(eventLogger.positionElementsStart()); - logs.push(eventLogger.positionElementsEnd()); - logs.push(eventLogger.waitForRenderStart()); - logs.push(eventLogger.waitForRenderEnd()); - logs.push(eventLogger.pdfStart()); - logs.push(eventLogger.addPdfImageStart()); - logs.push(eventLogger.addPdfImageEnd()); - logs.push(eventLogger.compilePdfStart()); - logs.push(eventLogger.compilePdfEnd()); - logs.push(eventLogger.pdfEnd({ pdfPages: 1, byteLengthPdf: 6666 })); - - const logData = logs.map((log) => ({ - event: log.kibana.screenshotting.action, - duration: log.event?.duration, + const screenshottingEnd = eventLogger.screenshottingTransaction(); + const openUrlEnd = eventLogger.log( + 'open the url to the Kibana application', + Actions.OPEN_URL, + 'screenshotting', + 'wait' + ); + openUrlEnd(); + const getElementPositionsEnd = eventLogger.log( + 'scan the page to find the boundaries of visualization elements', + Actions.GET_ELEMENT_POSITION_DATA, + 'screenshotting', + 'wait' + ); + getElementPositionsEnd(); + screenshottingEnd({ + metrics: { cpu: 12, cpuInPercentage: 0, memory: 450789, memoryInMegabytes: 449 }, + results: [], + }); + + const pdfEnd = eventLogger.pdfTransaction(); + const addImageEnd = eventLogger.log( + 'add image to the PDF file', + Actions.ADD_IMAGE, + 'generatePdf', + 'output' + ); + addImageEnd(); + pdfEnd({ pdf_pages: 1, byte_length_pdf: 6666 }); + + const logs = logSpy.mock.calls.map(([message, data]) => ({ + message, + event: data.kibana.screenshotting.action, + duration: data?.event?.duration, })); - expect(logData).toMatchInlineSnapshot(` + + expect(logs).toMatchInlineSnapshot(` Array [ Object { "duration": undefined, "event": "screenshot-pipeline-start", + "message": "screenshot pipeline - starting", }, Object { "duration": undefined, "event": "open-url-start", + "message": "open the url to the Kibana application - starting", }, Object { "duration": 3000, "event": "open-url-complete", + "message": "open the url to the Kibana application - completed", }, Object { "duration": undefined, "event": "get-element-position-data-start", + "message": "scan the page to find the boundaries of visualization elements - starting", }, Object { "duration": 5000, "event": "get-element-position-data-complete", + "message": "scan the page to find the boundaries of visualization elements - completed", }, Object { - "duration": undefined, - "event": "get-number-of-items-start", - }, - Object { - "duration": 7000, - "event": "get-number-of-items-complete", - }, - Object { - "duration": undefined, - "event": "get-render-errors-start", - }, - Object { - "duration": 9000, - "event": "get-render-errors-complete", - }, - Object { - "duration": undefined, - "event": "get-timerange-start", - }, - Object { - "duration": 11000, - "event": "get-timerange-complete", - }, - Object { - "duration": undefined, - "event": "inject-css-start", - }, - Object { - "duration": 13000, - "event": "inject-css-complete", - }, - Object { - "duration": undefined, - "event": "position-elements-start", - }, - Object { - "duration": 15000, - "event": "position-elements-complete", - }, - Object { - "duration": undefined, - "event": "wait-for-render-start", - }, - Object { - "duration": 17000, - "event": "wait-for-render-complete", + "duration": 20000, + "event": "screenshot-pipeline-complete", + "message": "screenshot pipeline - completed", }, Object { "duration": undefined, "event": "generate-pdf-start", + "message": "pdf generation - starting", }, Object { "duration": undefined, "event": "add-pdf-image-start", + "message": "add image to the PDF file - starting", }, Object { - "duration": 20000, + "duration": 9000, "event": "add-pdf-image-complete", + "message": "add image to the PDF file - completed", }, Object { - "duration": undefined, - "event": "compile-pdf-start", - }, - Object { - "duration": 22000, - "event": "compile-pdf-complete", - }, - Object { - "duration": 105000, + "duration": 27000, "event": "generate-pdf-complete", + "message": "pdf generation - completed", }, ] `); }); it('logs number of pixels', () => { - const logs = []; const elementPosition = { boundingClientRect: { width: 1350, height: 2000 }, scroll: {}, } as ElementPosition; - logs.push(eventLogger.getScreenshotStart({ elementPosition })); - logs.push(eventLogger.getScreenshotEnd({ byteLength: 4444, elementPosition })); + const endScreenshot = eventLogger.screenshot({ elementPosition }); + endScreenshot({ byteLength: 4444, elementPosition }); - const logData = logs.map((log) => ({ - message: log.message, - duration: log.event?.duration, - screenshotting: log.kibana.screenshotting, + const logData = logSpy.mock.calls.map(([message, data]) => ({ + message, + duration: data.event?.duration, + screenshotting: data.kibana.screenshotting, })); - expect( - logData.map((l) => ({ - duration: l.duration, - message: l.message, - action: l.screenshotting.action, - byte_length: l.screenshotting.byte_length, - pixels: l.screenshotting.pixels, - })) - ).toMatchInlineSnapshot(` + expect(logData).toMatchInlineSnapshot(` Array [ Object { - "action": "get-screenshots-start", - "byte_length": undefined, "duration": undefined, - "message": "capturing single screenshot", - "pixels": 10800000, + "message": "screenshot capture - starting", + "screenshotting": Object { + "action": "get-screenshots-start", + "pixels": 10800000, + "session_id": "89336347-677b-444b-8e94-4c5d026395ad", + }, }, Object { - "action": "get-screenshots-complete", - "byte_length": 4444, "duration": 2000, - "message": "single screenshot captured", - "pixels": 10800000, + "message": "screenshot capture - completed", + "screenshotting": Object { + "action": "get-screenshots-complete", + "byte_length": 4444, + "pixels": 10800000, + "session_id": "89336347-677b-444b-8e94-4c5d026395ad", + }, }, ] `); }); it('creates helpful error logs', () => { - const logs = []; - logs.push(eventLogger.screenshottingStart()); - logs.push(eventLogger.error(new Error('Something erroneous happened'), Actions.SCREENSHOTTING)); - - const logData = logs.map((log) => ({ - action: log.kibana.screenshotting.action, - message: log.message, - error: log.error, + eventLogger.screenshottingTransaction(); + eventLogger.error(new Error('Something erroneous happened'), Actions.SCREENSHOTTING); + + const logData = logSpy.mock.calls.map(([message, data]) => ({ + message, + action: data.kibana.screenshotting.action, + error: data.error, })); + expect(logData).toMatchInlineSnapshot(` Array [ Object { "action": "screenshot-pipeline-start", "error": undefined, - "message": "screenshot-pipeline starting", + "message": "screenshot pipeline - starting", }, Object { "action": "screenshot-pipeline-error", diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index b947853bd5a43..752d69d346048 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -31,13 +31,8 @@ export enum Actions { COMPILE = 'compile-pdf', } -enum SpanTypes { - SETUP = 'setup', - READ = 'read', - WAIT = 'wait', - CORRECT = 'correction', - OUTPUT = 'output', -} +export type TransactionType = 'generatePdf' | 'screenshotting'; +export type SpanTypes = 'setup' | 'read' | 'wait' | 'correction' | 'output'; export interface ScreenshottingAction extends LogMeta { event?: { @@ -83,33 +78,17 @@ interface GetScreenshotOptions { byteLength?: number; // byte length of completed completed current screenshot } -type SpanEntity = - | 'addPdfImage' - | 'compilePdf' - | 'createPage' - | 'getElementPositionData' - | 'getNumberOfItems' - | 'getRenderErrors' - | 'getScreenshot' - | 'getTimeRange' - | 'injectCss' - | 'openUrl' - | 'positionElements' - | 'waitForRender' - | 'waitForVisualization'; - -type TransactionEntity = 'generatePdf' | 'screenshotting'; - type SimpleEvent = Omit; type LogAdapter = ( message: string, - event: SimpleEvent, + suffix: 'start' | 'complete', + event: Partial, startTime?: Date | undefined -) => ScreenshottingAction; +) => void; -function logAdapter(logger: Logger, suffix: 'start' | 'complete', sessionId: string) { - const log: LogAdapter = (message, event, startTime) => { +function logAdapter(logger: Logger, sessionId: string) { + const log: LogAdapter = (message, suffix, event, startTime) => { let duration: number | undefined; if (startTime != null) { const start = startTime.valueOf(); @@ -117,8 +96,7 @@ function logAdapter(logger: Logger, suffix: 'start' | 'complete', sessionId: str } const interpretedAction = (event.action + `-${suffix}`) as Actions; - const logData: ScreenshottingAction = { - message, + const logData: Omit = { kibana: { screenshotting: { ...event, @@ -128,8 +106,8 @@ function logAdapter(logger: Logger, suffix: 'start' | 'complete', sessionId: str }, event: { duration, provider: PLUGIN_ID }, }; - logger.debug(message, logData); - return logData; + const newMessage = `${message} - ${suffix === 'start' ? 'starting' : 'completed'}`; + logger.debug(newMessage, logData); }; return log; } @@ -138,36 +116,19 @@ function logAdapter(logger: Logger, suffix: 'start' | 'complete', sessionId: str * A class to use internal state properties to log timing between actions in the screenshotting pipeline */ export class EventLogger { - private spans: Record = { - addPdfImage: null, - compilePdf: null, - createPage: null, - getElementPositionData: null, - getNumberOfItems: null, - getRenderErrors: null, - getScreenshot: null, - getTimeRange: null, - injectCss: null, - openUrl: null, - positionElements: null, - waitForRender: null, - waitForVisualization: null, - }; - - private transactions: Record = { + private spans = new Map(); + private transactions: Record = { screenshotting: null, generatePdf: null, }; private sessionId: string; // identifier to track all logs from one screenshotting flow - private logEventStart: LogAdapter; - private logEventEnd: LogAdapter; + private logEvent: LogAdapter; private timings: Partial> = {}; constructor(private readonly logger: Logger, private readonly config: ConfigType) { this.sessionId = uuid.v4(); - this.logEventStart = logAdapter(logger.get('events'), 'start', this.sessionId); - this.logEventEnd = logAdapter(logger.get('events'), 'complete', this.sessionId); + this.logEvent = logAdapter(logger.get('events'), this.sessionId); } private startTiming(a: Actions) { @@ -178,7 +139,7 @@ export class EventLogger { byteLength + screenshot.data.byteLength; /** - * @returns Logger + * @returns Logger - original logger */ public get kbnLogger() { return this.logger; @@ -186,358 +147,98 @@ export class EventLogger { // Methods for transactions - /** - * Signal when the overall screenshotting pipeline begins - * - * @returns void - */ - public screenshottingStart() { + public screenshottingTransaction() { this.transactions.screenshotting = apm.startTransaction(Actions.SCREENSHOTTING, PLUGIN_ID); this.startTiming(Actions.SCREENSHOTTING); - - return this.logEventStart('screenshot-pipeline starting', { action: Actions.SCREENSHOTTING }); - } - - /** - * Signal when the overall screenshotting pipeline finishes - * - * @param {CaptureResult} - outcome of screenshotting pipeline - * @returns void - */ - public screenshottingEnd({ metrics, results }: CaptureResult) { - const cpu = metrics?.cpu; - const memory = metrics?.memory; - const byteLength = results.reduce( - (totals, { screenshots }) => totals + screenshots.reduce(this.sumScreenshotsByteLength, 0), - 0 - ); - - this.transactions.screenshotting?.setLabel('cpu', cpu, false); - this.transactions.screenshotting?.setLabel('memory', memory, false); - this.transactions.screenshotting?.setLabel('byte-length', byteLength, false); - this.transactions.screenshotting?.end(); - - return this.logEventEnd( - 'screenshot-pipeline finished', - { action: Actions.SCREENSHOTTING, byte_length: byteLength, cpu, memory }, - this.timings[Actions.SCREENSHOTTING] - ); + this.logEvent('screenshot pipeline', 'start', { action: Actions.SCREENSHOTTING }); + + return ({ metrics, results }: CaptureResult) => { + const cpu = metrics?.cpu; + const memory = metrics?.memory; + const byteLength = results.reduce( + (totals, { screenshots }) => totals + screenshots.reduce(this.sumScreenshotsByteLength, 0), + 0 + ); + + this.transactions.screenshotting?.setLabel('cpu', cpu, false); + this.transactions.screenshotting?.setLabel('memory', memory, false); + this.transactions.screenshotting?.setLabel('byte-length', byteLength, false); + this.transactions.screenshotting?.end(); + this.logEvent( + 'screenshot pipeline', + 'complete', + { action: Actions.SCREENSHOTTING, byte_length: byteLength, cpu, memory }, + this.timings[Actions.SCREENSHOTTING] + ); + }; } - public pdfStart() { + public pdfTransaction() { this.transactions.generatePdf = apm.startTransaction(Actions.PDF, PLUGIN_ID); this.startTiming(Actions.PDF); - - return this.logEventStart('pdf generation starting', { action: Actions.PDF }); - } - - /** - * @param .byteLengthPdf - length of bytes of the PDF file - * @param .pdfPages - number of pages in the PDF file - * @returns void - */ - public pdfEnd({ byteLengthPdf, pdfPages }: { byteLengthPdf: number; pdfPages: number }) { - this.transactions.generatePdf?.setLabel('byte-length', byteLengthPdf, false); - this.transactions.generatePdf?.setLabel('pdf-pages', pdfPages, false); - this.transactions.generatePdf?.end(); - - return this.logEventEnd( - 'pdf generation finished', - { - action: Actions.PDF, - byte_length_pdf: byteLengthPdf, - pdf_pages: pdfPages, - }, - this.timings[Actions.PDF] - ); - } - - // Methods for spans - - public getElementPositionsStart() { - this.spans.getElementPositionData = this.transactions.screenshotting?.startSpan( - Actions.GET_ELEMENT_POSITION_DATA, - SpanTypes.READ - ); - this.startTiming(Actions.GET_ELEMENT_POSITION_DATA); - - return this.logEventStart('getting element position data', { - action: Actions.GET_ELEMENT_POSITION_DATA, - }); - } - - /** - * @param .elementPositions - number of elements that have a position to know about - * @returns void - */ - public getElementPositionsEnd({ elementPositions }: { elementPositions?: number }) { - this.spans.getElementPositionData?.end(); - - return this.logEventEnd( - 'element position data read', - { action: Actions.GET_ELEMENT_POSITION_DATA, element_positions: elementPositions }, - this.timings[Actions.GET_ELEMENT_POSITION_DATA] - ); + this.logEvent('pdf generation', 'start', { action: Actions.PDF }); + + return (action: Partial) => { + this.transactions.generatePdf?.setLabel('byte-length', action.byte_length_pdf, false); + this.transactions.generatePdf?.setLabel('pdf-pages', action.pdf_pages, false); + this.transactions.generatePdf?.end(); + this.logEvent( + 'pdf generation', + 'complete', + { ...action, action: Actions.PDF }, + this.timings[Actions.PDF] + ); + }; } - public getNumberOfItemsStart() { - this.spans.getNumberOfItems = this.transactions.screenshotting?.startSpan( - Actions.GET_NUMBER_OF_ITEMS, - SpanTypes.READ - ); - this.startTiming(Actions.GET_NUMBER_OF_ITEMS); + // General method for spans - return this.logEventStart('getting number of visualization items', { - action: Actions.GET_NUMBER_OF_ITEMS, - }); - } - - /** - * @param .itemsCount - number of renderable items found on the page - * @returns void - */ - public getNumberOfItemsEnd({ itemsCount }: { itemsCount: number }) { - this.spans.getNumberOfItems?.end(); - - return this.logEventEnd( - 'received number of visualization items', - { - action: Actions.GET_NUMBER_OF_ITEMS, - items_count: itemsCount, - }, - this.timings[Actions.GET_NUMBER_OF_ITEMS] - ); - } + public log(message: string, action: Actions, transaction: TransactionType, type: SpanTypes) { + const txn = this.transactions[transaction]; + const span = txn?.startSpan(action, type); - public getRenderErrorsStart() { - this.spans.getRenderErrors = this.transactions.screenshotting?.startSpan( - Actions.GET_RENDER_ERRORS, - SpanTypes.READ - ); - this.startTiming(Actions.GET_RENDER_ERRORS); + this.spans.set(action, span); + this.startTiming(action); + this.logEvent(message, 'start', { action }); - return this.logEventStart('starting scan for rendering errors', { - action: Actions.GET_RENDER_ERRORS, - }); + return (metricData: Partial = {}) => { + span?.end(); + this.logEvent(message, 'complete', { ...metricData, action }, this.timings[action]); + }; } - /** - * @param .renderErrors - total number of render errors found on the page - * @returns void - */ - public getRenderErrorsEnd({ renderErrors }: { renderErrors?: number }) { - this.spans.getRenderErrors?.end(); - - return this.logEventEnd( - 'finished scanning for rendering errors', - { - action: Actions.GET_RENDER_ERRORS, - render_errors: renderErrors, - }, - this.timings[Actions.GET_RENDER_ERRORS] - ); - } + // Methods for specific part of screenshotting private getPixels(elementPosition: ElementPosition, zoom: number) { const { width, height } = elementPosition.boundingClientRect; return width * zoom * (height * zoom); } - /** - * @param GetScreenshotOptions - context of the screenshot to be taken - * @returns void - */ - public getScreenshotStart({ elementPosition }: GetScreenshotOptions) { - this.spans.getScreenshot = this.transactions.screenshotting?.startSpan( + public screenshot({ elementPosition }: GetScreenshotOptions) { + this.spans.set( Actions.GET_SCREENSHOT, - SpanTypes.READ + this.transactions.screenshotting?.startSpan(Actions.GET_SCREENSHOT, 'read') ); this.startTiming(Actions.GET_SCREENSHOT); - - return this.logEventStart('capturing single screenshot', { + this.logEvent('screenshot capture', 'start', { action: Actions.GET_SCREENSHOT, pixels: this.getPixels(elementPosition, this.config.capture.zoom), }); - } - - /** - * @param GetScreenshotOptions - context of the screenshot taken - * @returns void - */ - public getScreenshotEnd({ byteLength, elementPosition }: Required) { - this.spans.getScreenshot?.end(); - - return this.logEventEnd( - 'single screenshot captured', - { - action: Actions.GET_SCREENSHOT, - byte_length: byteLength, - pixels: this.getPixels(elementPosition, this.config.capture.zoom), - }, - this.timings[Actions.GET_SCREENSHOT] - ); - } - - public getTimeRangeStart() { - this.spans.getTimeRange = this.transactions.screenshotting?.startSpan( - Actions.GET_TIMERANGE, - SpanTypes.READ - ); - this.startTiming(Actions.GET_TIMERANGE); - - return this.logEventStart('getting time range', { action: Actions.GET_TIMERANGE }); - } - - public getTimeRangeEnd() { - this.spans.getTimeRange?.end(); - - return this.logEventEnd( - 'received time range', - { action: Actions.GET_TIMERANGE }, - this.timings[Actions.GET_TIMERANGE] - ); - } - - public injectCssStart() { - this.spans.injectCss = this.transactions.screenshotting?.startSpan( - Actions.INJECT_CSS, - SpanTypes.CORRECT - ); - this.startTiming(Actions.INJECT_CSS); - - return this.logEventStart('injecting css', { action: Actions.INJECT_CSS }); - } - - public injectCssEnd() { - this.spans.injectCss?.end(); - - return this.logEventEnd( - 'finished injecting css', - { action: Actions.INJECT_CSS }, - this.timings[Actions.INJECT_CSS] - ); - } - - public openUrlStart() { - this.spans.openUrl = this.transactions.screenshotting?.startSpan( - Actions.OPEN_URL, - SpanTypes.WAIT - ); - this.startTiming(Actions.OPEN_URL); - - return this.logEventStart('opening url', { action: Actions.OPEN_URL }); - } - - public openUrlEnd() { - this.spans.openUrl?.end(); - - return this.logEventEnd( - 'finished opening url', - { action: Actions.OPEN_URL }, - this.timings[Actions.OPEN_URL] - ); - } - - public positionElementsStart() { - this.spans.positionElements = this.transactions.screenshotting?.startSpan( - Actions.REPOSITION, - SpanTypes.CORRECT - ); - this.startTiming(Actions.REPOSITION); - - return this.logEventStart('positioning elements', { action: Actions.REPOSITION }); - } - - public positionElementsEnd() { - this.spans.positionElements?.end(); - - return this.logEventEnd( - 'finished positioning elements', - { action: Actions.REPOSITION }, - this.timings[Actions.REPOSITION] - ); - } - - public waitForRenderStart() { - this.spans.waitForRender = this.transactions.screenshotting?.startSpan( - Actions.WAIT_RENDER, - SpanTypes.WAIT - ); - this.startTiming(Actions.WAIT_RENDER); - - return this.logEventStart('waiting for render to complete', { action: Actions.WAIT_RENDER }); - } - - public waitForRenderEnd() { - this.spans.waitForRender?.end(); - - return this.logEventEnd( - 'finished waiting for render to complete', - { action: Actions.WAIT_RENDER }, - this.timings[Actions.WAIT_RENDER] - ); - } - - public waitForVisualizationStart() { - this.spans.waitForVisualization = this.transactions.screenshotting?.startSpan( - Actions.WAIT_VISUALIZATIONS, - SpanTypes.WAIT - ); - this.startTiming(Actions.WAIT_VISUALIZATIONS); - - return this.logEventStart('waiting for visualizations', { - action: Actions.WAIT_VISUALIZATIONS, - }); - } - - public waitForVisualizationEnd() { - this.spans.waitForVisualization?.end(); - - return this.logEventEnd( - 'finished waiting for visualizations', - { action: Actions.WAIT_VISUALIZATIONS }, - this.timings[Actions.WAIT_VISUALIZATIONS] - ); - } - - public addPdfImageStart() { - this.spans.addPdfImage = this.transactions.generatePdf?.startSpan( - Actions.ADD_IMAGE, - SpanTypes.OUTPUT - ); - this.startTiming(Actions.ADD_IMAGE); - - return this.logEventStart('adding pdf image', { action: Actions.ADD_IMAGE }); - } - public addPdfImageEnd() { - this.spans.addPdfImage?.end(); + return ({ byteLength }: Required) => { + this.spans.get(Actions.GET_SCREENSHOT)?.end(); - return this.logEventEnd( - 'pdf image added', - { action: Actions.ADD_IMAGE }, - this.timings[Actions.ADD_IMAGE] - ); - } - - public compilePdfStart() { - this.spans.compilePdf = this.transactions.generatePdf?.startSpan( - Actions.COMPILE, - SpanTypes.OUTPUT - ); - this.startTiming(Actions.COMPILE); - - return this.logEventStart('compiling pdf file', { action: Actions.COMPILE }); - } - - public compilePdfEnd() { - this.spans.compilePdf?.end(); - - return this.logEventEnd( - 'pdf file compiled', - { action: Actions.COMPILE }, - this.timings[Actions.COMPILE] - ); + return this.logEvent( + 'screenshot capture', + 'complete', + { + action: Actions.GET_SCREENSHOT, + byte_length: byteLength, + pixels: this.getPixels(elementPosition, this.config.capture.zoom), + }, + this.timings[Actions.GET_SCREENSHOT] + ); + }; } /** @@ -563,7 +264,5 @@ export class EventLogger { }, }; this.logger.debug('an error occurred', logData); - - return logData; } } diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index d4da179d3b1ee..305534dce8ab6 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -38,7 +38,12 @@ export const getElementPositionAndAttributes = async ( eventLogger: EventLogger, layout: Layout ): Promise => { - eventLogger.getElementPositionsStart(); + const spanEnd = eventLogger.log( + 'get element position data', + Actions.GET_ELEMENT_POSITION_DATA, + 'screenshotting', + 'read' + ); const { screenshot: screenshotSelector } = layout.selectors; // data-shared-items-container let elementsPositionAndAttributes: ElementsPositionAndAttribute[] | null; @@ -90,7 +95,7 @@ export const getElementPositionAndAttributes = async ( elementsPositionAndAttributes = null; } - eventLogger.getElementPositionsEnd({ elementPositions: elementsPositionAndAttributes?.length }); + spanEnd({ element_positions: elementsPositionAndAttributes?.length }); return elementsPositionAndAttributes; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts index d22dd55b9e31a..9d9698bfd9a72 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts @@ -16,7 +16,12 @@ export const getNumberOfItems = async ( timeout: number, layout: Layout ): Promise => { - eventLogger.getNumberOfItemsStart(); + const spanEnd = eventLogger.log( + 'get the number of visualization items on the page', + Actions.GET_NUMBER_OF_ITEMS, + 'screenshotting', + 'read' + ); const { renderComplete: renderCompleteSelector, itemsCountAttribute } = layout.selectors; let itemsCount: number; @@ -60,7 +65,7 @@ export const getNumberOfItems = async ( throw newError; } - eventLogger.getNumberOfItemsEnd({ itemsCount }); + spanEnd({ items_count: itemsCount }); return itemsCount; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts index 6e56103e93e1f..e95bd63f33b85 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts @@ -8,14 +8,19 @@ import type { HeadlessChromiumDriver } from '../browsers'; import type { Layout } from '../layouts'; import { CONTEXT_GETRENDERERRORS } from './constants'; -import { EventLogger } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; export const getRenderErrors = async ( browser: HeadlessChromiumDriver, eventLogger: EventLogger, layout: Layout ): Promise => { - eventLogger.getRenderErrorsStart(); + const spanEnd = eventLogger.log( + 'look for render errors', + Actions.GET_RENDER_ERRORS, + 'screenshotting', + 'read' + ); const { kbnLogger } = eventLogger; const errorsFound: undefined | string[] = await browser.evaluate( @@ -44,7 +49,7 @@ export const getRenderErrors = async ( kbnLogger.warn(`Found ${renderErrors} error messages. See report object for more information.`); } - eventLogger.getRenderErrorsEnd({ renderErrors }); + spanEnd({ render_errors: renderErrors }); return errorsFound; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index 177b7abc2f7b7..37b2180e4c0fc 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -38,7 +38,7 @@ export const getScreenshots = async ( for (let i = 0; i < elementsPositionAndAttributes.length; i++) { const item = elementsPositionAndAttributes[i]; - eventLogger.getScreenshotStart({ + const spanEnd = eventLogger.screenshot({ elementPosition: item.position, }); @@ -54,7 +54,7 @@ export const getScreenshots = async ( description: item.attributes.description, }); - eventLogger.getScreenshotEnd({ + spanEnd({ elementPosition: item.position, byteLength: data.byteLength, }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts index e0125d3fcbc9f..b5c746dcaee23 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts @@ -8,14 +8,19 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_GETTIMERANGE } from './constants'; -import { EventLogger } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; export const getTimeRange = async ( browser: HeadlessChromiumDriver, eventLogger: EventLogger, layout: Layout ): Promise => { - eventLogger.getTimeRangeStart(); + const spanEnd = eventLogger.log( + 'looking for time range', + Actions.GET_TIMERANGE, + 'screenshotting', + 'read' + ); const timeRange = await browser.evaluate( { @@ -43,7 +48,7 @@ export const getTimeRange = async ( eventLogger.kbnLogger.info(`timeRange: ${timeRange}`); } - eventLogger.getTimeRangeEnd(); + spanEnd(); return timeRange; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/index.ts b/x-pack/plugins/screenshotting/server/screenshots/index.ts index 84e7a9c5b96ac..35327b3645311 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/index.ts @@ -218,14 +218,14 @@ export class Screenshots { getScreenshots(options: ScreenshotOptions): Observable; getScreenshots(options: ScreenshotOptions): Observable { const eventLogger = new EventLogger(this.logger, this.config); - eventLogger.screenshottingStart(); + const transactionEnd = eventLogger.screenshottingTransaction(); const layout = this.createLayout(options); const captureOptions = this.getCaptureOptions(options); return this.captureScreenshots(eventLogger, layout, captureOptions).pipe( tap((results) => { - eventLogger.screenshottingEnd(results); + transactionEnd(results); }), mergeMap((result) => { switch (options.format) { diff --git a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts index b866d19750ce7..9ea8b330d7070 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts @@ -24,7 +24,12 @@ export const injectCustomCss = async ( return; } - eventLogger.injectCssStart(); + const spanEnd = eventLogger.log( + 'inject CSS into the page', + Actions.INJECT_CSS, + 'screenshotting', + 'correction' + ); const buffer = await fsp.readFile(filePath); try { @@ -48,5 +53,5 @@ export const injectCustomCss = async ( ); } - eventLogger.injectCssEnd(); + spanEnd(); }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index d58ae28b3daeb..34332c7227305 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -194,10 +194,15 @@ export class ScreenshotObservableHandler { // allows for them to be displayed properly in many cases await injectCustomCss(driver, eventLogger, layout); - this.eventLogger.positionElementsStart(); + const spanEnd = this.eventLogger.log( + 'get positions of visualization elements', + Actions.GET_ELEMENT_POSITION_DATA, + 'screenshotting', + 'read' + ); // position panel elements for print layout await layout.positionElements?.(driver, eventLogger.kbnLogger); - this.eventLogger.positionElementsEnd(); + spanEnd(); await waitForRenderComplete( driver, diff --git a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts index 870681c52ec26..e1bf12726ba21 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts @@ -19,7 +19,7 @@ export const openUrl = async ( context: Context, headers: Headers ): Promise => { - eventLogger.openUrlStart(); + const spanEnd = eventLogger.log('open url', Actions.OPEN_URL, 'screenshotting', 'wait'); // If we're moving to another page in the app, we'll want to wait for the app to tell us // it's loaded the next page. @@ -36,5 +36,5 @@ export const openUrl = async ( throw newError; } - eventLogger.openUrlEnd(); + spanEnd(); }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts index c632d69dc7e91..497a6c84fe3a9 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_WAITFORRENDER } from './constants'; -import { EventLogger } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; export const waitForRenderComplete = async ( browser: HeadlessChromiumDriver, @@ -16,7 +16,12 @@ export const waitForRenderComplete = async ( loadDelay: number, layout: Layout ) => { - eventLogger.waitForRenderStart(); + const spanEnd = eventLogger.log( + 'wait for render complete', + Actions.WAIT_RENDER, + 'screenshotting', + 'wait' + ); return await browser .evaluate( @@ -66,6 +71,6 @@ export const waitForRenderComplete = async ( eventLogger.kbnLogger ) .then(() => { - eventLogger.waitForRenderEnd(); + spanEnd(); }); }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts index 9761f54eabba4..fc4ccb6370062 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts @@ -41,7 +41,12 @@ export const waitForVisualizations = async ( toEqual: number, layout: Layout ): Promise => { - eventLogger.waitForVisualizationStart(); + const spanEnd = eventLogger.log( + 'waiting for each visualization to complete rendering', + Actions.WAIT_VISUALIZATIONS, + 'screenshotting', + 'wait' + ); const { renderComplete: renderCompleteSelector } = layout.selectors; @@ -64,5 +69,5 @@ export const waitForVisualizations = async ( throw newError; } - eventLogger.waitForVisualizationEnd(); + spanEnd(); }; From f6c687505048199cb8a42eb37624ab62d325cdb1 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 15:07:41 -0700 Subject: [PATCH 12/28] fix test --- .../server/screenshots/event_logger/index.test.ts | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index 427ef2ab36a2c..c1b99d723c0bd 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -5,6 +5,7 @@ * 2.0. */ +import { omit } from 'lodash'; import moment from 'moment'; import { loggingSystemMock } from '@kbn/core/server/mocks'; import { Actions, EventLogger, ScreenshottingAction } from '.'; @@ -125,7 +126,7 @@ describe('Event Logger', () => { `); }); - it('logs number of pixels', () => { + it('logs the number of pixels', () => { const elementPosition = { boundingClientRect: { width: 1350, height: 2000 }, scroll: {}, @@ -136,7 +137,7 @@ describe('Event Logger', () => { const logData = logSpy.mock.calls.map(([message, data]) => ({ message, duration: data.event?.duration, - screenshotting: data.kibana.screenshotting, + screenshotting: omit(data.kibana.screenshotting, 'session_id'), })); expect(logData).toMatchInlineSnapshot(` @@ -147,7 +148,6 @@ describe('Event Logger', () => { "screenshotting": Object { "action": "get-screenshots-start", "pixels": 10800000, - "session_id": "89336347-677b-444b-8e94-4c5d026395ad", }, }, Object { @@ -157,7 +157,6 @@ describe('Event Logger', () => { "action": "get-screenshots-complete", "byte_length": 4444, "pixels": 10800000, - "session_id": "89336347-677b-444b-8e94-4c5d026395ad", }, }, ] From 902e8df8a94d3e050fef8903e2b31b0254ee084b Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 15:43:50 -0700 Subject: [PATCH 13/28] fix sessionId not showing in error logs --- .../screenshots/event_logger/index.test.ts | 89 +++++++++++++++---- .../server/screenshots/event_logger/index.ts | 72 ++++++++++----- 2 files changed, 122 insertions(+), 39 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index c1b99d723c0bd..a04aed1c3e9b9 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -5,13 +5,16 @@ * 2.0. */ -import { omit } from 'lodash'; import moment from 'moment'; import { loggingSystemMock } from '@kbn/core/server/mocks'; import { Actions, EventLogger, ScreenshottingAction } from '.'; import { ElementPosition } from '../get_element_position_data'; import { ConfigType } from '../../config'; +jest.mock('uuid', () => ({ + v4: () => 'NEW_UUID', +})); + type EventLoggerArgs = [message: string, meta: ScreenshottingAction]; describe('Event Logger', () => { let eventLogger: EventLogger; @@ -66,61 +69,96 @@ describe('Event Logger', () => { const logs = logSpy.mock.calls.map(([message, data]) => ({ message, - event: data.kibana.screenshotting.action, duration: data?.event?.duration, + screenshotting: data?.kibana?.screenshotting, })); expect(logs).toMatchInlineSnapshot(` Array [ Object { "duration": undefined, - "event": "screenshot-pipeline-start", "message": "screenshot pipeline - starting", + "screenshotting": Object { + "action": "screenshot-pipeline-start", + "session_id": "NEW_UUID", + }, }, Object { "duration": undefined, - "event": "open-url-start", "message": "open the url to the Kibana application - starting", + "screenshotting": Object { + "action": "open-url-start", + "session_id": "NEW_UUID", + }, }, Object { "duration": 3000, - "event": "open-url-complete", "message": "open the url to the Kibana application - completed", + "screenshotting": Object { + "action": "open-url-complete", + "session_id": "NEW_UUID", + }, }, Object { "duration": undefined, - "event": "get-element-position-data-start", "message": "scan the page to find the boundaries of visualization elements - starting", + "screenshotting": Object { + "action": "get-element-position-data-start", + "session_id": "NEW_UUID", + }, }, Object { "duration": 5000, - "event": "get-element-position-data-complete", "message": "scan the page to find the boundaries of visualization elements - completed", + "screenshotting": Object { + "action": "get-element-position-data-complete", + "session_id": "NEW_UUID", + }, }, Object { "duration": 20000, - "event": "screenshot-pipeline-complete", "message": "screenshot pipeline - completed", + "screenshotting": Object { + "action": "screenshot-pipeline-complete", + "byte_length": 0, + "cpu": 12, + "memory": 450789, + "session_id": "NEW_UUID", + }, }, Object { "duration": undefined, - "event": "generate-pdf-start", "message": "pdf generation - starting", + "screenshotting": Object { + "action": "generate-pdf-start", + "session_id": "NEW_UUID", + }, }, Object { "duration": undefined, - "event": "add-pdf-image-start", "message": "add image to the PDF file - starting", + "screenshotting": Object { + "action": "add-pdf-image-start", + "session_id": "NEW_UUID", + }, }, Object { "duration": 9000, - "event": "add-pdf-image-complete", "message": "add image to the PDF file - completed", + "screenshotting": Object { + "action": "add-pdf-image-complete", + "session_id": "NEW_UUID", + }, }, Object { "duration": 27000, - "event": "generate-pdf-complete", "message": "pdf generation - completed", + "screenshotting": Object { + "action": "generate-pdf-complete", + "byte_length_pdf": 6666, + "pdf_pages": 1, + "session_id": "NEW_UUID", + }, }, ] `); @@ -137,7 +175,7 @@ describe('Event Logger', () => { const logData = logSpy.mock.calls.map(([message, data]) => ({ message, duration: data.event?.duration, - screenshotting: omit(data.kibana.screenshotting, 'session_id'), + screenshotting: data.kibana.screenshotting, })); expect(logData).toMatchInlineSnapshot(` @@ -148,6 +186,7 @@ describe('Event Logger', () => { "screenshotting": Object { "action": "get-screenshots-start", "pixels": 10800000, + "session_id": "NEW_UUID", }, }, Object { @@ -157,6 +196,7 @@ describe('Event Logger', () => { "action": "get-screenshots-complete", "byte_length": 4444, "pixels": 10800000, + "session_id": "NEW_UUID", }, }, ] @@ -165,30 +205,45 @@ describe('Event Logger', () => { it('creates helpful error logs', () => { eventLogger.screenshottingTransaction(); + eventLogger.log('opening the url', Actions.OPEN_URL, 'screenshotting', 'wait'); eventLogger.error(new Error('Something erroneous happened'), Actions.SCREENSHOTTING); const logData = logSpy.mock.calls.map(([message, data]) => ({ message, - action: data.kibana.screenshotting.action, error: data.error, + screenshotting: data.kibana.screenshotting, })); expect(logData).toMatchInlineSnapshot(` Array [ Object { - "action": "screenshot-pipeline-start", "error": undefined, "message": "screenshot pipeline - starting", + "screenshotting": Object { + "action": "screenshot-pipeline-start", + "session_id": "NEW_UUID", + }, + }, + Object { + "error": undefined, + "message": "opening the url - starting", + "screenshotting": Object { + "action": "open-url-start", + "session_id": "NEW_UUID", + }, }, Object { - "action": "screenshot-pipeline-error", "error": Object { "code": undefined, "message": "Something erroneous happened", "stack_trace": undefined, "type": undefined, }, - "message": "an error occurred", + "message": "Error: Something erroneous happened", + "screenshotting": Object { + "action": "screenshot-pipeline-error", + "session_id": "NEW_UUID", + }, }, ] `); diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 752d69d346048..4d6332dad30fe 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -82,11 +82,44 @@ type SimpleEvent = Omit, startTime?: Date | undefined ) => void; +function fillLogData( + message: string, + event: Partial, + suffix: 'start' | 'complete' | 'error', + sessionId: string, + duration: number | undefined +) { + let newMessage = message; + if (suffix !== 'error') { + newMessage = `${message} - ${suffix === 'start' ? 'starting' : 'completed'}`; + } + + let interpretedAction: string; + if (suffix === 'error') { + interpretedAction = event.action + '-error'; + } else { + interpretedAction = event.action + `-${suffix}`; + } + + const logData: ScreenshottingAction = { + message: newMessage, + kibana: { + screenshotting: { + ...event, + action: interpretedAction as Actions, + session_id: sessionId, + }, + }, + event: { duration, provider: PLUGIN_ID }, + }; + return logData; +} + function logAdapter(logger: Logger, sessionId: string) { const log: LogAdapter = (message, suffix, event, startTime) => { let duration: number | undefined; @@ -95,19 +128,8 @@ function logAdapter(logger: Logger, sessionId: string) { duration = new Date(Date.now()).valueOf() - start.valueOf(); } - const interpretedAction = (event.action + `-${suffix}`) as Actions; - const logData: Omit = { - kibana: { - screenshotting: { - ...event, - action: interpretedAction, - session_id: sessionId, - }, - }, - event: { duration, provider: PLUGIN_ID }, - }; - const newMessage = `${message} - ${suffix === 'start' ? 'starting' : 'completed'}`; - logger.debug(newMessage, logData); + const logData = fillLogData(message, event, suffix, sessionId, duration); + logger.debug(logData.message, logData); }; return log; } @@ -228,7 +250,7 @@ export class EventLogger { return ({ byteLength }: Required) => { this.spans.get(Actions.GET_SCREENSHOT)?.end(); - return this.logEvent( + this.logEvent( 'screenshot capture', 'complete', { @@ -251,18 +273,24 @@ export class EventLogger { public error(error: ErrorAction | string, action: Actions) { const isError = typeof error === 'object'; this.logger.error(error as Error); - - const logData = { - message: 'an error occurred', - kibana: { screenshotting: { action: `${action}-error` } }, - event: { provider: PLUGIN_ID }, + const message = `Error: ${isError ? error.message : error}`; + + const errorData = { + ...fillLogData( + message, + { action }, + 'error', + this.sessionId, + undefined // + ), error: { - message: isError ? error.message : undefined, + message: isError ? error.message : error, code: isError ? error.code : undefined, stack_trace: isError ? error.stack_trace : undefined, type: isError ? error.type : undefined, }, }; - this.logger.debug('an error occurred', logData); + + this.logger.debug(message, errorData); } } From bfdc37ebf15c49fb005da2ce84d15e1277d22f21 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 16:09:35 -0700 Subject: [PATCH 14/28] prettify message --- .../screenshots/event_logger/index.test.ts | 28 +++++++++---------- .../server/screenshots/event_logger/index.ts | 2 +- 2 files changed, 15 insertions(+), 15 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index a04aed1c3e9b9..775eacde70a96 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -77,7 +77,7 @@ describe('Event Logger', () => { Array [ Object { "duration": undefined, - "message": "screenshot pipeline - starting", + "message": "starting: screenshot pipeline", "screenshotting": Object { "action": "screenshot-pipeline-start", "session_id": "NEW_UUID", @@ -85,7 +85,7 @@ describe('Event Logger', () => { }, Object { "duration": undefined, - "message": "open the url to the Kibana application - starting", + "message": "starting: open the url to the Kibana application", "screenshotting": Object { "action": "open-url-start", "session_id": "NEW_UUID", @@ -93,7 +93,7 @@ describe('Event Logger', () => { }, Object { "duration": 3000, - "message": "open the url to the Kibana application - completed", + "message": "completed: open the url to the Kibana application", "screenshotting": Object { "action": "open-url-complete", "session_id": "NEW_UUID", @@ -101,7 +101,7 @@ describe('Event Logger', () => { }, Object { "duration": undefined, - "message": "scan the page to find the boundaries of visualization elements - starting", + "message": "starting: scan the page to find the boundaries of visualization elements", "screenshotting": Object { "action": "get-element-position-data-start", "session_id": "NEW_UUID", @@ -109,7 +109,7 @@ describe('Event Logger', () => { }, Object { "duration": 5000, - "message": "scan the page to find the boundaries of visualization elements - completed", + "message": "completed: scan the page to find the boundaries of visualization elements", "screenshotting": Object { "action": "get-element-position-data-complete", "session_id": "NEW_UUID", @@ -117,7 +117,7 @@ describe('Event Logger', () => { }, Object { "duration": 20000, - "message": "screenshot pipeline - completed", + "message": "completed: screenshot pipeline", "screenshotting": Object { "action": "screenshot-pipeline-complete", "byte_length": 0, @@ -128,7 +128,7 @@ describe('Event Logger', () => { }, Object { "duration": undefined, - "message": "pdf generation - starting", + "message": "starting: pdf generation", "screenshotting": Object { "action": "generate-pdf-start", "session_id": "NEW_UUID", @@ -136,7 +136,7 @@ describe('Event Logger', () => { }, Object { "duration": undefined, - "message": "add image to the PDF file - starting", + "message": "starting: add image to the PDF file", "screenshotting": Object { "action": "add-pdf-image-start", "session_id": "NEW_UUID", @@ -144,7 +144,7 @@ describe('Event Logger', () => { }, Object { "duration": 9000, - "message": "add image to the PDF file - completed", + "message": "completed: add image to the PDF file", "screenshotting": Object { "action": "add-pdf-image-complete", "session_id": "NEW_UUID", @@ -152,7 +152,7 @@ describe('Event Logger', () => { }, Object { "duration": 27000, - "message": "pdf generation - completed", + "message": "completed: pdf generation", "screenshotting": Object { "action": "generate-pdf-complete", "byte_length_pdf": 6666, @@ -182,7 +182,7 @@ describe('Event Logger', () => { Array [ Object { "duration": undefined, - "message": "screenshot capture - starting", + "message": "starting: screenshot capture", "screenshotting": Object { "action": "get-screenshots-start", "pixels": 10800000, @@ -191,7 +191,7 @@ describe('Event Logger', () => { }, Object { "duration": 2000, - "message": "screenshot capture - completed", + "message": "completed: screenshot capture", "screenshotting": Object { "action": "get-screenshots-complete", "byte_length": 4444, @@ -218,7 +218,7 @@ describe('Event Logger', () => { Array [ Object { "error": undefined, - "message": "screenshot pipeline - starting", + "message": "starting: screenshot pipeline", "screenshotting": Object { "action": "screenshot-pipeline-start", "session_id": "NEW_UUID", @@ -226,7 +226,7 @@ describe('Event Logger', () => { }, Object { "error": undefined, - "message": "opening the url - starting", + "message": "starting: opening the url", "screenshotting": Object { "action": "open-url-start", "session_id": "NEW_UUID", diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 4d6332dad30fe..8490a6e1686e9 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -96,7 +96,7 @@ function fillLogData( ) { let newMessage = message; if (suffix !== 'error') { - newMessage = `${message} - ${suffix === 'start' ? 'starting' : 'completed'}`; + newMessage = `${suffix === 'start' ? 'starting' : 'completed'}: ${message}`; } let interpretedAction: string; From 1514727cabc2ce1d9281fbf0b46af1f0629ce93f Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 16:26:36 -0700 Subject: [PATCH 15/28] more logging improvements --- .../server/screenshots/event_logger/index.test.ts | 2 +- .../server/screenshots/event_logger/index.ts | 1 - .../server/screenshots/get_number_of_items.ts | 14 ++++++++------ 3 files changed, 9 insertions(+), 8 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index 775eacde70a96..e8a6453ee0853 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -169,7 +169,7 @@ describe('Event Logger', () => { boundingClientRect: { width: 1350, height: 2000 }, scroll: {}, } as ElementPosition; - const endScreenshot = eventLogger.screenshot({ elementPosition }); + const endScreenshot = eventLogger.startScreenshot({ elementPosition }); endScreenshot({ byteLength: 4444, elementPosition }); const logData = logSpy.mock.calls.map(([message, data]) => ({ diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 8490a6e1686e9..493fbc1452e03 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -272,7 +272,6 @@ export class EventLogger { */ public error(error: ErrorAction | string, action: Actions) { const isError = typeof error === 'object'; - this.logger.error(error as Error); const message = `Error: ${isError ? error.message : error}`; const errorData = { diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts index 9d9698bfd9a72..c1f6cc648245f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts @@ -16,6 +16,7 @@ export const getNumberOfItems = async ( timeout: number, layout: Layout ): Promise => { + const { kbnLogger } = eventLogger; const spanEnd = eventLogger.log( 'get the number of visualization items on the page', Actions.GET_NUMBER_OF_ITEMS, @@ -34,7 +35,7 @@ export const getNumberOfItems = async ( `${renderCompleteSelector},[${itemsCountAttribute}]`, { timeout }, { context: CONTEXT_READMETADATA }, - eventLogger.kbnLogger + kbnLogger ); // returns the value of the `itemsCountAttribute` if it's there, otherwise @@ -55,14 +56,15 @@ export const getNumberOfItems = async ( args: [renderCompleteSelector, itemsCountAttribute], }, { context: CONTEXT_GETNUMBEROFITEMS }, - eventLogger.kbnLogger + kbnLogger ); } catch (error) { - const newError = new Error( - `An error occurred when trying to read the page for visualization panel info: ${error.message}` + kbnLogger.error(error); + eventLogger.error( + `An error occurred when trying to read the page for visualization panel info: ${error.message}`, + Actions.GET_NUMBER_OF_ITEMS ); - eventLogger.error(newError, Actions.GET_NUMBER_OF_ITEMS); - throw newError; + throw error; } spanEnd({ items_count: itemsCount }); From d5a83bc75efaebbd7b80be927c42665fcc879368 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 16:27:08 -0700 Subject: [PATCH 16/28] add specific error logging around get screenshots --- .../server/screenshots/get_screenshots.ts | 46 +++++++++++-------- 1 file changed, 27 insertions(+), 19 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index 37b2180e4c0fc..93ac8f0d0d57c 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -6,7 +6,7 @@ */ import type { HeadlessChromiumDriver } from '../browsers'; -import { EventLogger } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; import type { ElementsPositionAndAttribute } from './get_element_position_data'; export interface Screenshot { @@ -36,28 +36,36 @@ export const getScreenshots = async ( const screenshots: Screenshot[] = []; - for (let i = 0; i < elementsPositionAndAttributes.length; i++) { - const item = elementsPositionAndAttributes[i]; - const spanEnd = eventLogger.screenshot({ - elementPosition: item.position, - }); + try { + for (let i = 0; i < elementsPositionAndAttributes.length; i++) { + const item = elementsPositionAndAttributes[i]; + const endScreenshot = eventLogger.startScreenshot({ + elementPosition: item.position, + }); - const data = await browser.screenshot(item.position); + const data = await browser.screenshot(item.position); - if (!data?.byteLength) { - throw new Error(`Failure in getScreenshots! Screenshot data is void`); - } + if (!data?.byteLength) { + throw new Error(`Failure in getScreenshots! Screenshot data is void`); + } - screenshots.push({ - data, - title: item.attributes.title, - description: item.attributes.description, - }); + screenshots.push({ + data, + title: item.attributes.title, + description: item.attributes.description, + }); - spanEnd({ - elementPosition: item.position, - byteLength: data.byteLength, - }); + endScreenshot({ + elementPosition: item.position, + byteLength: data.byteLength, + }); + } + } catch (error) { + kbnLogger.error(error); + eventLogger.error( + `An error occurred when trying to capture screenshots: ${error.message}`, + Actions.GET_NUMBER_OF_ITEMS + ); } kbnLogger.info(`screenshots taken: ${screenshots.length}`); From ea79bb44bb7cb8bc2d9e68434b17811bf96406f5 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 16:38:35 -0700 Subject: [PATCH 17/28] function level comments --- .../server/screenshots/event_logger/index.ts | 74 +++++++++++++------ 1 file changed, 51 insertions(+), 23 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 493fbc1452e03..021bfd2729919 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -73,11 +73,6 @@ interface ErrorAction { type?: string; } -interface GetScreenshotOptions { - elementPosition: ElementPosition; - byteLength?: number; // byte length of completed completed current screenshot -} - type SimpleEvent = Omit; type LogAdapter = ( @@ -87,6 +82,10 @@ type LogAdapter = ( startTime?: Date | undefined ) => void; +type ScreenshottingEndFn = ({ metrics, results }: CaptureResult) => void; +type GeneratePdfEndFn = (action: Partial) => void; +type LogEndFn = (metricData?: Partial) => void; + function fillLogData( message: string, event: Partial, @@ -167,14 +166,17 @@ export class EventLogger { return this.logger; } - // Methods for transactions - - public screenshottingTransaction() { + /** + * Specific method for logging the beginning of the screenshotting pipeline + * + * @returns {ScreenshottingEndFn} + */ + public screenshottingTransaction(): ScreenshottingEndFn { this.transactions.screenshotting = apm.startTransaction(Actions.SCREENSHOTTING, PLUGIN_ID); this.startTiming(Actions.SCREENSHOTTING); this.logEvent('screenshot pipeline', 'start', { action: Actions.SCREENSHOTTING }); - return ({ metrics, results }: CaptureResult) => { + return ({ metrics, results }) => { const cpu = metrics?.cpu; const memory = metrics?.memory; const byteLength = results.reduce( @@ -195,12 +197,17 @@ export class EventLogger { }; } - public pdfTransaction() { + /** + * Specific method for logging the beginning of the PDF generation pipeline + * + * @returns {GeneratePdfEndFn} + */ + public pdfTransaction(): GeneratePdfEndFn { this.transactions.generatePdf = apm.startTransaction(Actions.PDF, PLUGIN_ID); this.startTiming(Actions.PDF); this.logEvent('pdf generation', 'start', { action: Actions.PDF }); - return (action: Partial) => { + return (action) => { this.transactions.generatePdf?.setLabel('byte-length', action.byte_length_pdf, false); this.transactions.generatePdf?.setLabel('pdf-pages', action.pdf_pages, false); this.transactions.generatePdf?.end(); @@ -215,7 +222,21 @@ export class EventLogger { // General method for spans - public log(message: string, action: Actions, transaction: TransactionType, type: SpanTypes) { + /** + * General event logging function + * + * @param {string} message + * @param {Actions} action - action type for kibana.screenshotting.action + * @param {TransactionType} transaction - name of the internal APM transaction in which to associate the span + * @param {SpanTypes} type - identifier of the span type + * @returns {LogEndFn} - function to log the end of the span + */ + public log( + message: string, + action: Actions, + transaction: TransactionType, + type: SpanTypes + ): LogEndFn { const txn = this.transactions[transaction]; const span = txn?.startSpan(action, type); @@ -223,42 +244,49 @@ export class EventLogger { this.startTiming(action); this.logEvent(message, 'start', { action }); - return (metricData: Partial = {}) => { + return (metricData = {}) => { span?.end(); this.logEvent(message, 'complete', { ...metricData, action }, this.timings[action]); }; } - // Methods for specific part of screenshotting - private getPixels(elementPosition: ElementPosition, zoom: number) { const { width, height } = elementPosition.boundingClientRect; return width * zoom * (height * zoom); } - public screenshot({ elementPosition }: GetScreenshotOptions) { + /** + * Specific method for capturing an action around screenshot capture, + * needed to convert layout data into number of pixels for logging + * + * @param {GetScreenshotOptions} + * @param {ElementPosition} .elementPosition - info for logging the screenshot dimension metrics + * @returns {LogEndFn} - function to log the end of screenshot capture + */ + public startScreenshot({ elementPosition }: { elementPosition: ElementPosition }): LogEndFn { + const action = Actions.GET_SCREENSHOT; this.spans.set( - Actions.GET_SCREENSHOT, + action, this.transactions.screenshotting?.startSpan(Actions.GET_SCREENSHOT, 'read') ); - this.startTiming(Actions.GET_SCREENSHOT); + this.startTiming(action); this.logEvent('screenshot capture', 'start', { action: Actions.GET_SCREENSHOT, pixels: this.getPixels(elementPosition, this.config.capture.zoom), }); - return ({ byteLength }: Required) => { - this.spans.get(Actions.GET_SCREENSHOT)?.end(); + return (metricData) => { + this.spans.get(action)?.end(); this.logEvent( 'screenshot capture', 'complete', { - action: Actions.GET_SCREENSHOT, - byte_length: byteLength, + action, + byte_length: metricData?.byte_length, pixels: this.getPixels(elementPosition, this.config.capture.zoom), }, - this.timings[Actions.GET_SCREENSHOT] + this.timings[action] ); }; } From 595f479111e20280f4c60b40799e4d6bae611107 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 17:02:26 -0700 Subject: [PATCH 18/28] error handling around getting render errors --- .../server/screenshots/get_render_errors.ts | 62 +++++++++++-------- .../server/screenshots/get_screenshots.ts | 5 +- 2 files changed, 38 insertions(+), 29 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts index e95bd63f33b85..133a9d415f37e 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts @@ -15,6 +15,8 @@ export const getRenderErrors = async ( eventLogger: EventLogger, layout: Layout ): Promise => { + const { kbnLogger } = eventLogger; + const spanEnd = eventLogger.log( 'look for render errors', Actions.GET_RENDER_ERRORS, @@ -22,34 +24,44 @@ export const getRenderErrors = async ( 'read' ); - const { kbnLogger } = eventLogger; - const errorsFound: undefined | string[] = await browser.evaluate( - { - fn: (errorSelector, errorAttribute) => { - const visualizations: Element[] = Array.from(document.querySelectorAll(errorSelector)); - const errors: string[] = []; - - visualizations.forEach((visualization) => { - const errorMessage = visualization.getAttribute(errorAttribute); - if (errorMessage) { - errors.push(errorMessage); - } - }); - - return errors.length ? errors : undefined; + let errorsFound: undefined | string[]; + try { + errorsFound = await browser.evaluate( + { + fn: (errorSelector, errorAttribute) => { + const visualizations: Element[] = Array.from(document.querySelectorAll(errorSelector)); + const errors: string[] = []; + + visualizations.forEach((visualization) => { + const errorMessage = visualization.getAttribute(errorAttribute); + if (errorMessage) { + errors.push(errorMessage); + } + }); + + return errors.length ? errors : undefined; + }, + args: [layout.selectors.renderError, layout.selectors.renderErrorAttribute], }, - args: [layout.selectors.renderError, layout.selectors.renderErrorAttribute], - }, - { context: CONTEXT_GETRENDERERRORS }, - kbnLogger - ); + { context: CONTEXT_GETRENDERERRORS }, + kbnLogger + ); - const renderErrors = errorsFound?.length; - if (renderErrors) { - kbnLogger.warn(`Found ${renderErrors} error messages. See report object for more information.`); - } + const renderErrors = errorsFound?.length; + if (renderErrors) { + kbnLogger.warn( + `Found ${renderErrors} error messages. See report object for more information.` + ); + } - spanEnd({ render_errors: renderErrors }); + spanEnd({ render_errors: renderErrors }); + } catch (error) { + kbnLogger.error(error); + eventLogger.error( + `An error occurred when checking the page for rendering errors`, + Actions.GET_RENDER_ERRORS + ); + } return errorsFound; }; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index 93ac8f0d0d57c..c8e72924a0133 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -55,10 +55,7 @@ export const getScreenshots = async ( description: item.attributes.description, }); - endScreenshot({ - elementPosition: item.position, - byteLength: data.byteLength, - }); + endScreenshot({ byte_length: data.byteLength }); } } catch (error) { kbnLogger.error(error); From 9c8c189699834fb948aa8d1d12b970493a044c8f Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 17:16:57 -0700 Subject: [PATCH 19/28] ensure original logger.error always still called --- .../server/screenshots/get_element_position_data.ts | 5 ++++- .../server/screenshots/get_number_of_items.ts | 5 +---- .../screenshotting/server/screenshots/get_render_errors.ts | 5 +---- .../screenshotting/server/screenshots/get_screenshots.ts | 5 +---- x-pack/plugins/screenshotting/server/screenshots/index.ts | 1 + .../screenshotting/server/screenshots/inject_css.ts | 5 ++++- .../screenshotting/server/screenshots/observable.ts | 4 +--- .../plugins/screenshotting/server/screenshots/open_url.ts | 5 ++++- .../server/screenshots/wait_for_visualizations.ts | 7 ++++--- 9 files changed, 21 insertions(+), 21 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index 305534dce8ab6..cffb0cf5ebb25 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -38,6 +38,8 @@ export const getElementPositionAndAttributes = async ( eventLogger: EventLogger, layout: Layout ): Promise => { + const { kbnLogger } = eventLogger; + const spanEnd = eventLogger.log( 'get element position data', Actions.GET_ELEMENT_POSITION_DATA, @@ -82,7 +84,7 @@ export const getElementPositionAndAttributes = async ( args: [screenshotSelector, { title: 'data-title', description: 'data-description' }], }, { context: CONTEXT_ELEMENTATTRIBUTES }, - eventLogger.kbnLogger + kbnLogger ); if (!elementsPositionAndAttributes?.length) { @@ -91,6 +93,7 @@ export const getElementPositionAndAttributes = async ( ); } } catch (err) { + kbnLogger.error(err); eventLogger.error(err, Actions.GET_ELEMENT_POSITION_DATA); elementsPositionAndAttributes = null; } diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts index c1f6cc648245f..fbaf9f20d191f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts @@ -60,10 +60,7 @@ export const getNumberOfItems = async ( ); } catch (error) { kbnLogger.error(error); - eventLogger.error( - `An error occurred when trying to read the page for visualization panel info: ${error.message}`, - Actions.GET_NUMBER_OF_ITEMS - ); + eventLogger.error(error, Actions.GET_NUMBER_OF_ITEMS); throw error; } diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts index 133a9d415f37e..e13570f27502c 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts @@ -57,10 +57,7 @@ export const getRenderErrors = async ( spanEnd({ render_errors: renderErrors }); } catch (error) { kbnLogger.error(error); - eventLogger.error( - `An error occurred when checking the page for rendering errors`, - Actions.GET_RENDER_ERRORS - ); + eventLogger.error(error, Actions.GET_RENDER_ERRORS); } return errorsFound; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index c8e72924a0133..6b30b2e9a6453 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -59,10 +59,7 @@ export const getScreenshots = async ( } } catch (error) { kbnLogger.error(error); - eventLogger.error( - `An error occurred when trying to capture screenshots: ${error.message}`, - Actions.GET_NUMBER_OF_ITEMS - ); + eventLogger.error(error, Actions.GET_SCREENSHOT); } kbnLogger.info(`screenshots taken: ${screenshots.length}`); diff --git a/x-pack/plugins/screenshotting/server/screenshots/index.ts b/x-pack/plugins/screenshotting/server/screenshots/index.ts index 35327b3645311..441b484605992 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/index.ts @@ -145,6 +145,7 @@ export class Screenshots { catchError((error) => { screen.checkPageIsOpen(); // this fails the job if the browser has closed + this.logger.error(error); eventLogger.error(error, Actions.SCREENSHOTTING); return of({ ...DEFAULT_SETUP_RESULT, error }); // allow failover screenshot capture }), diff --git a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts index 9ea8b330d7070..54167a77b64cc 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts @@ -24,6 +24,8 @@ export const injectCustomCss = async ( return; } + const { kbnLogger } = eventLogger; + const spanEnd = eventLogger.log( 'inject CSS into the page', Actions.INJECT_CSS, @@ -44,9 +46,10 @@ export const injectCustomCss = async ( args: [buffer.toString()], }, { context: CONTEXT_INJECTCSS }, - eventLogger.kbnLogger + kbnLogger ); } catch (err) { + kbnLogger.error(err); eventLogger.error(err, Actions.INJECT_CSS); throw new Error( `An error occurred when trying to update Kibana CSS for reporting. ${err.message}` diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index 34332c7227305..71aee9c400ae2 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -245,9 +245,7 @@ export class ScreenshotObservableHandler { try { screenshots = await getScreenshots(this.driver, this.eventLogger, elements); } catch (e) { - const newError = new errors.FailedToCaptureScreenshot(e.message); - this.eventLogger.error(newError, Actions.GET_SCREENSHOT); - throw newError; + throw new errors.FailedToCaptureScreenshot(e.message); } const { timeRange, error: setupError, renderErrors } = data; diff --git a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts index e1bf12726ba21..a252ede608b72 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts @@ -19,6 +19,7 @@ export const openUrl = async ( context: Context, headers: Headers ): Promise => { + const { kbnLogger } = eventLogger; const spanEnd = eventLogger.log('open url', Actions.OPEN_URL, 'screenshotting', 'wait'); // If we're moving to another page in the app, we'll want to wait for the app to tell us @@ -27,8 +28,10 @@ export const openUrl = async ( const waitForSelector = page > 1 ? `[data-shared-page="${page}"]` : DEFAULT_PAGELOAD_SELECTOR; try { - await browser.open(url, { context, headers, waitForSelector, timeout }, eventLogger.kbnLogger); + await browser.open(url, { context, headers, waitForSelector, timeout }, kbnLogger); } catch (err) { + kbnLogger.error(err); + const newError = new Error( `An error occurred when trying to open the Kibana URL: ${err.message}` ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts index fc4ccb6370062..676467a885cfd 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts @@ -41,6 +41,7 @@ export const waitForVisualizations = async ( toEqual: number, layout: Layout ): Promise => { + const { kbnLogger } = eventLogger; const spanEnd = eventLogger.log( 'waiting for each visualization to complete rendering', Actions.WAIT_VISUALIZATIONS, @@ -50,8 +51,7 @@ export const waitForVisualizations = async ( const { renderComplete: renderCompleteSelector } = layout.selectors; - const logger = eventLogger.kbnLogger; - logger.debug(`waiting for ${toEqual} rendered elements to be in the DOM`); + kbnLogger.debug(`waiting for ${toEqual} rendered elements to be in the DOM`); try { await browser.waitFor({ @@ -60,8 +60,9 @@ export const waitForVisualizations = async ( timeout, }); - logger.debug(`found ${toEqual} rendered elements in the DOM`); + kbnLogger.debug(`found ${toEqual} rendered elements in the DOM`); } catch (err) { + kbnLogger.error(err); const newError = new Error( `An error occurred when trying to wait for ${toEqual} visualizations to finish rendering. ${err.message}` ); From 7fd2b507c0e89349032bae6240c069dc2f943211 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 17:23:06 -0700 Subject: [PATCH 20/28] fix error logs not having the right logging context --- .../screenshotting/server/screenshots/event_logger/index.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 021bfd2729919..82b063dc401df 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -318,6 +318,6 @@ export class EventLogger { }, }; - this.logger.debug(message, errorData); + this.logger.get('events').debug(message, errorData); } } From 1ed749bfedf66ad49064023354e7e057946b602b Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 17:38:39 -0700 Subject: [PATCH 21/28] more error logging around pdfMaker --- .../server/formats/pdf/pdf_maker/index.ts | 47 ++++++++++--------- 1 file changed, 26 insertions(+), 21 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts index d3b03c836c7ed..20c39fcb351b9 100644 --- a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts +++ b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts @@ -28,37 +28,42 @@ export async function pngsToPdf({ packageInfo, eventLogger, }: PngsToPdfArgs): Promise<{ buffer: Buffer; pages: number }> { + const { kbnLogger } = eventLogger; const transactionEnd = eventLogger.pdfTransaction(); - const pdfMaker = new PdfMaker(layout, logo, packageInfo, eventLogger.kbnLogger); - if (title) { - pdfMaker.setTitle(title); - } - results.forEach((result) => { - result.screenshots.forEach((png) => { - const spanEnd = eventLogger.log( - 'add image to PDF file', - Actions.ADD_IMAGE, - 'generatePdf', - 'output' - ); - pdfMaker.addImage(png.data, { - title: png.title ?? undefined, - description: png.description ?? undefined, - }); - spanEnd(); - }); - }); let buffer: Uint8Array | null = null; + let pdfMaker: PdfMaker | null = null; try { + pdfMaker = new PdfMaker(layout, logo, packageInfo, kbnLogger); + if (title) { + pdfMaker.setTitle(title); + } + results.forEach((result) => { + result.screenshots.forEach((png) => { + const spanEnd = eventLogger.log( + 'add image to PDF file', + Actions.ADD_IMAGE, + 'generatePdf', + 'output' + ); + pdfMaker?.addImage(png.data, { + title: png.title ?? undefined, + description: png.description ?? undefined, + }); + spanEnd(); + }); + }); + const spanEnd = eventLogger.log('compile PDF file', Actions.COMPILE, 'generatePdf', 'output'); buffer = await pdfMaker.generate(); spanEnd(); const byteLength = buffer?.byteLength ?? 0; transactionEnd({ byte_length_pdf: byteLength, pdf_pages: pdfMaker.getPageCount() }); - } catch (err) { - throw err; + } catch (error) { + kbnLogger.error(error); + eventLogger.error(error, Actions.COMPILE); + throw error; } return { buffer: Buffer.from(buffer.buffer), pages: pdfMaker.getPageCount() }; From 35dd0a80b71aa2134668e01d6eda09ec00547cc0 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 17:43:01 -0700 Subject: [PATCH 22/28] more error logging around re-position elements --- .../screenshotting/server/screenshots/observable.ts | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index 71aee9c400ae2..949705cd4d225 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -200,9 +200,14 @@ export class ScreenshotObservableHandler { 'screenshotting', 'read' ); - // position panel elements for print layout - await layout.positionElements?.(driver, eventLogger.kbnLogger); - spanEnd(); + try { + // position panel elements for print layout + await layout.positionElements?.(driver, eventLogger.kbnLogger); + spanEnd(); + } catch (error) { + eventLogger.error(error, Actions.GET_ELEMENT_POSITION_DATA); + throw error; + } await waitForRenderComplete( driver, From dae5003cdd4fa66d0e18958523ca75565b33a622 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 17:47:08 -0700 Subject: [PATCH 23/28] fix test --- .../server/screenshots/__snapshots__/index.test.ts.snap | 4 ++-- .../server/screenshots/event_logger/index.test.ts | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap b/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap index c0971c9b95763..1b3826ce9980d 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap +++ b/x-pack/plugins/screenshotting/server/screenshots/__snapshots__/index.test.ts.snap @@ -20,7 +20,7 @@ Array [ }, }, ], - "error": [Error: The "wait for elements" phase encountered an error: Error: An error occurred when trying to read the page for visualization panel info: Mock error!], + "error": [Error: The "wait for elements" phase encountered an error: Error: Mock error!], "renderErrors": undefined, "screenshots": Array [ Object { @@ -63,7 +63,7 @@ Array [ }, }, ], - "error": [Error: The "wait for elements" phase encountered an error: Error: An error occurred when trying to read the page for visualization panel info: Mock error!], + "error": [Error: The "wait for elements" phase encountered an error: Error: Mock error!], "renderErrors": undefined, "screenshots": Array [ Object { diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index e8a6453ee0853..67c93aab0680a 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -170,7 +170,7 @@ describe('Event Logger', () => { scroll: {}, } as ElementPosition; const endScreenshot = eventLogger.startScreenshot({ elementPosition }); - endScreenshot({ byteLength: 4444, elementPosition }); + endScreenshot({ byte_length: 4444 }); const logData = logSpy.mock.calls.map(([message, data]) => ({ message, From 195b10832af98f0aeeb1a7ae6eabeaed4ce14686 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 20 Apr 2022 17:47:30 -0700 Subject: [PATCH 24/28] fix error re-throw after logging --- .../server/screenshots/get_element_position_data.ts | 1 + .../screenshotting/server/screenshots/get_render_errors.ts | 1 + .../plugins/screenshotting/server/screenshots/get_screenshots.ts | 1 + 3 files changed, 3 insertions(+) diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index cffb0cf5ebb25..e7f43e5feffe3 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -96,6 +96,7 @@ export const getElementPositionAndAttributes = async ( kbnLogger.error(err); eventLogger.error(err, Actions.GET_ELEMENT_POSITION_DATA); elementsPositionAndAttributes = null; + // no throw } spanEnd({ element_positions: elementsPositionAndAttributes?.length }); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts index e13570f27502c..ac5f327f9ded5 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts @@ -58,6 +58,7 @@ export const getRenderErrors = async ( } catch (error) { kbnLogger.error(error); eventLogger.error(error, Actions.GET_RENDER_ERRORS); + throw error; } return errorsFound; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index 6b30b2e9a6453..64a5a9afde99a 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -60,6 +60,7 @@ export const getScreenshots = async ( } catch (error) { kbnLogger.error(error); eventLogger.error(error, Actions.GET_SCREENSHOT); + throw error; } kbnLogger.info(`screenshots taken: ${screenshots.length}`); From d2e544791a15b7d1eaa819e9656dc29ba95dc1b0 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Tue, 3 May 2022 12:40:13 -0700 Subject: [PATCH 25/28] use apm to capture the error --- .../screenshotting/server/screenshots/event_logger/index.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 82b063dc401df..861eecda4a023 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -319,5 +319,6 @@ export class EventLogger { }; this.logger.get('events').debug(message, errorData); + apm.captureError(error as Error | string); } } From c8a7b741ad08662202d6a052a6ad42abd47e0a54 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Tue, 3 May 2022 13:20:41 -0700 Subject: [PATCH 26/28] simplify eventLogger api --- .../screenshots/event_logger/index.test.ts | 12 +++- .../server/screenshots/event_logger/index.ts | 63 +++++++------------ .../server/screenshots/get_screenshots.ts | 10 ++- 3 files changed, 37 insertions(+), 48 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index 67c93aab0680a..97976abc6d17d 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -169,7 +169,13 @@ describe('Event Logger', () => { boundingClientRect: { width: 1350, height: 2000 }, scroll: {}, } as ElementPosition; - const endScreenshot = eventLogger.startScreenshot({ elementPosition }); + const endScreenshot = eventLogger.log( + 'screenshot capture test', + Actions.GET_SCREENSHOT, + 'screenshotting', + 'read', + eventLogger.getPixelsFromElementPosition(elementPosition) + ); endScreenshot({ byte_length: 4444 }); const logData = logSpy.mock.calls.map(([message, data]) => ({ @@ -182,7 +188,7 @@ describe('Event Logger', () => { Array [ Object { "duration": undefined, - "message": "starting: screenshot capture", + "message": "starting: screenshot capture test", "screenshotting": Object { "action": "get-screenshots-start", "pixels": 10800000, @@ -191,7 +197,7 @@ describe('Event Logger', () => { }, Object { "duration": 2000, - "message": "completed: screenshot capture", + "message": "completed: screenshot capture test", "screenshotting": Object { "action": "get-screenshots-complete", "byte_length": 4444, diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 861eecda4a023..4f27f9248458c 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -83,8 +83,8 @@ type LogAdapter = ( ) => void; type ScreenshottingEndFn = ({ metrics, results }: CaptureResult) => void; -type GeneratePdfEndFn = (action: Partial) => void; -type LogEndFn = (metricData?: Partial) => void; +type GeneratePdfEndFn = (action: Partial) => void; +type LogEndFn = (metricData?: Partial) => void; function fillLogData( message: string, @@ -229,68 +229,47 @@ export class EventLogger { * @param {Actions} action - action type for kibana.screenshotting.action * @param {TransactionType} transaction - name of the internal APM transaction in which to associate the span * @param {SpanTypes} type - identifier of the span type + * @param {metricsPre} type - optional metrics to add to the "start" log of the event * @returns {LogEndFn} - function to log the end of the span */ public log( message: string, action: Actions, transaction: TransactionType, - type: SpanTypes + type: SpanTypes, + metricsPre: Partial = {} ): LogEndFn { const txn = this.transactions[transaction]; const span = txn?.startSpan(action, type); this.spans.set(action, span); this.startTiming(action); - this.logEvent(message, 'start', { action }); + this.logEvent(message, 'start', { ...metricsPre, action }); return (metricData = {}) => { span?.end(); - this.logEvent(message, 'complete', { ...metricData, action }, this.timings[action]); - }; - } - - private getPixels(elementPosition: ElementPosition, zoom: number) { - const { width, height } = elementPosition.boundingClientRect; - return width * zoom * (height * zoom); - } - - /** - * Specific method for capturing an action around screenshot capture, - * needed to convert layout data into number of pixels for logging - * - * @param {GetScreenshotOptions} - * @param {ElementPosition} .elementPosition - info for logging the screenshot dimension metrics - * @returns {LogEndFn} - function to log the end of screenshot capture - */ - public startScreenshot({ elementPosition }: { elementPosition: ElementPosition }): LogEndFn { - const action = Actions.GET_SCREENSHOT; - this.spans.set( - action, - this.transactions.screenshotting?.startSpan(Actions.GET_SCREENSHOT, 'read') - ); - this.startTiming(action); - this.logEvent('screenshot capture', 'start', { - action: Actions.GET_SCREENSHOT, - pixels: this.getPixels(elementPosition, this.config.capture.zoom), - }); - - return (metricData) => { - this.spans.get(action)?.end(); - this.logEvent( - 'screenshot capture', + message, 'complete', - { - action, - byte_length: metricData?.byte_length, - pixels: this.getPixels(elementPosition, this.config.capture.zoom), - }, + { ...metricsPre, ...metricData, action }, this.timings[action] ); }; } + /** + * Helper function to create the "metricPre" data needed to log the start + * of a screenshot capture event. + */ + public getPixelsFromElementPosition( + elementPosition: ElementPosition + ): Pick { + const { width, height } = elementPosition.boundingClientRect; + const zoom = this.config.capture.zoom; + const pixels = width * zoom * (height * zoom); + return { pixels }; + } + /** * General error logger * diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index 64a5a9afde99a..d072eb9e71cf4 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -39,9 +39,13 @@ export const getScreenshots = async ( try { for (let i = 0; i < elementsPositionAndAttributes.length; i++) { const item = elementsPositionAndAttributes[i]; - const endScreenshot = eventLogger.startScreenshot({ - elementPosition: item.position, - }); + const endScreenshot = eventLogger.log( + 'screenshot capture', + Actions.GET_SCREENSHOT, + 'screenshotting', + 'read', + eventLogger.getPixelsFromElementPosition(item.position) + ); const data = await browser.screenshot(item.position); From 94a1f3375d39d368d5244203c51c7739811eb97a Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Tue, 3 May 2022 14:24:13 -0700 Subject: [PATCH 27/28] single startTransaction method --- .../server/formats/pdf/index.ts | 4 +- .../server/formats/pdf/pdf_maker/index.ts | 15 ++- .../screenshots/event_logger/index.test.ts | 25 ++-- .../server/screenshots/event_logger/index.ts | 112 ++++++++---------- .../screenshots/get_element_position_data.ts | 4 +- .../server/screenshots/get_number_of_items.ts | 4 +- .../server/screenshots/get_render_errors.ts | 4 +- .../server/screenshots/get_screenshots.ts | 4 +- .../server/screenshots/get_time_range.ts | 4 +- .../server/screenshots/index.ts | 17 ++- .../server/screenshots/inject_css.ts | 4 +- .../server/screenshots/observable.ts | 4 +- .../server/screenshots/open_url.ts | 9 +- .../server/screenshots/wait_for_render.ts | 4 +- .../screenshots/wait_for_visualizations.ts | 4 +- 15 files changed, 112 insertions(+), 106 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/formats/pdf/index.ts b/x-pack/plugins/screenshotting/server/formats/pdf/index.ts index 0219f4472751a..ce28c53bb5f88 100644 --- a/x-pack/plugins/screenshotting/server/formats/pdf/index.ts +++ b/x-pack/plugins/screenshotting/server/formats/pdf/index.ts @@ -12,7 +12,7 @@ import type { LayoutParams } from '../../../common'; import { LayoutTypes } from '../../../common'; import type { Layout } from '../../layouts'; import type { CaptureMetrics, CaptureOptions, CaptureResult } from '../../screenshots'; -import { Actions, EventLogger } from '../../screenshots/event_logger'; +import { EventLogger, Transactions } from '../../screenshots/event_logger'; import { pngsToPdf } from './pdf_maker'; /** @@ -121,7 +121,7 @@ export async function toPdf( }; } catch (error) { eventLogger.kbnLogger.error(`Could not generate the PDF buffer!`); - eventLogger.error(error, Actions.PDF); + eventLogger.error(error, Transactions.PDF); throw error; } diff --git a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts index 20c39fcb351b9..5a71cf5047247 100644 --- a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts +++ b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts @@ -8,7 +8,7 @@ import type { PackageInfo } from '@kbn/core/server'; import type { Layout } from '../../../layouts'; import type { CaptureResult } from '../../../screenshots'; -import { Actions, EventLogger } from '../../../screenshots/event_logger'; +import { Actions, EventLogger, Transactions } from '../../../screenshots/event_logger'; import { PdfMaker } from './pdfmaker'; interface PngsToPdfArgs { @@ -29,7 +29,7 @@ export async function pngsToPdf({ eventLogger, }: PngsToPdfArgs): Promise<{ buffer: Buffer; pages: number }> { const { kbnLogger } = eventLogger; - const transactionEnd = eventLogger.pdfTransaction(); + const transactionEnd = eventLogger.startTransaction(Transactions.PDF); let buffer: Uint8Array | null = null; let pdfMaker: PdfMaker | null = null; @@ -43,7 +43,7 @@ export async function pngsToPdf({ const spanEnd = eventLogger.log( 'add image to PDF file', Actions.ADD_IMAGE, - 'generatePdf', + Transactions.PDF, 'output' ); pdfMaker?.addImage(png.data, { @@ -54,12 +54,17 @@ export async function pngsToPdf({ }); }); - const spanEnd = eventLogger.log('compile PDF file', Actions.COMPILE, 'generatePdf', 'output'); + const spanEnd = eventLogger.log( + 'compile PDF file', + Actions.COMPILE, + Transactions.PDF, + 'output' + ); buffer = await pdfMaker.generate(); spanEnd(); const byteLength = buffer?.byteLength ?? 0; - transactionEnd({ byte_length_pdf: byteLength, pdf_pages: pdfMaker.getPageCount() }); + transactionEnd({ labels: { byte_length_pdf: byteLength, pdf_pages: pdfMaker.getPageCount() } }); } catch (error) { kbnLogger.error(error); eventLogger.error(error, Actions.COMPILE); diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index 97976abc6d17d..2fcc12738455a 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -7,7 +7,7 @@ import moment from 'moment'; import { loggingSystemMock } from '@kbn/core/server/mocks'; -import { Actions, EventLogger, ScreenshottingAction } from '.'; +import { Actions, EventLogger, ScreenshottingAction, Transactions } from '.'; import { ElementPosition } from '../get_element_position_data'; import { ConfigType } from '../../config'; @@ -37,35 +37,34 @@ describe('Event Logger', () => { }); it('creates logs for the events and includes durations and event payload data', () => { - const screenshottingEnd = eventLogger.screenshottingTransaction(); + const screenshottingEnd = eventLogger.startTransaction(Transactions.SCREENSHOTTING); const openUrlEnd = eventLogger.log( 'open the url to the Kibana application', Actions.OPEN_URL, - 'screenshotting', + Transactions.SCREENSHOTTING, 'wait' ); openUrlEnd(); const getElementPositionsEnd = eventLogger.log( 'scan the page to find the boundaries of visualization elements', Actions.GET_ELEMENT_POSITION_DATA, - 'screenshotting', + Transactions.SCREENSHOTTING, 'wait' ); getElementPositionsEnd(); screenshottingEnd({ - metrics: { cpu: 12, cpuInPercentage: 0, memory: 450789, memoryInMegabytes: 449 }, - results: [], + labels: { cpu: 12, cpu_percentage: 0, memory: 450789, memory_mb: 449 }, }); - const pdfEnd = eventLogger.pdfTransaction(); + const pdfEnd = eventLogger.startTransaction(Transactions.PDF); const addImageEnd = eventLogger.log( 'add image to the PDF file', Actions.ADD_IMAGE, - 'generatePdf', + Transactions.PDF, 'output' ); addImageEnd(); - pdfEnd({ pdf_pages: 1, byte_length_pdf: 6666 }); + pdfEnd({ labels: { pdf_pages: 1, byte_length_pdf: 6666 } }); const logs = logSpy.mock.calls.map(([message, data]) => ({ message, @@ -172,7 +171,7 @@ describe('Event Logger', () => { const endScreenshot = eventLogger.log( 'screenshot capture test', Actions.GET_SCREENSHOT, - 'screenshotting', + Transactions.SCREENSHOTTING, 'read', eventLogger.getPixelsFromElementPosition(elementPosition) ); @@ -210,9 +209,9 @@ describe('Event Logger', () => { }); it('creates helpful error logs', () => { - eventLogger.screenshottingTransaction(); - eventLogger.log('opening the url', Actions.OPEN_URL, 'screenshotting', 'wait'); - eventLogger.error(new Error('Something erroneous happened'), Actions.SCREENSHOTTING); + eventLogger.startTransaction(Transactions.SCREENSHOTTING); + eventLogger.log('opening the url', Actions.OPEN_URL, Transactions.SCREENSHOTTING, 'wait'); + eventLogger.error(new Error('Something erroneous happened'), Transactions.SCREENSHOTTING); const logData = logSpy.mock.calls.map(([message, data]) => ({ message, diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index 4f27f9248458c..d017b4e82c8fc 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -15,7 +15,6 @@ import { ElementPosition } from '../get_element_position_data'; import { Screenshot } from '../get_screenshots'; export enum Actions { - SCREENSHOTTING = 'screenshot-pipeline', OPEN_URL = 'open-url', GET_ELEMENT_POSITION_DATA = 'get-element-position-data', GET_NUMBER_OF_ITEMS = 'get-number-of-items', @@ -26,12 +25,15 @@ export enum Actions { WAIT_RENDER = 'wait-for-render', WAIT_VISUALIZATIONS = 'wait-for-visualizations', GET_SCREENSHOT = 'get-screenshots', - PDF = 'generate-pdf', ADD_IMAGE = 'add-pdf-image', COMPILE = 'compile-pdf', } -export type TransactionType = 'generatePdf' | 'screenshotting'; +export enum Transactions { + SCREENSHOTTING = 'screenshot-pipeline', + PDF = 'generate-pdf', +} + export type SpanTypes = 'setup' | 'read' | 'wait' | 'correction' | 'output'; export interface ScreenshottingAction extends LogMeta { @@ -43,7 +45,7 @@ export interface ScreenshottingAction extends LogMeta { message: string; kibana: { screenshotting: { - action: Actions; + action: Actions | Transactions; session_id: string; // chromium stats @@ -82,8 +84,8 @@ type LogAdapter = ( startTime?: Date | undefined ) => void; -type ScreenshottingEndFn = ({ metrics, results }: CaptureResult) => void; -type GeneratePdfEndFn = (action: Partial) => void; +type Labels = Record; +type TransactionEndFn = (args: { labels: Partial }) => void; type LogEndFn = (metricData?: Partial) => void; function fillLogData( @@ -138,27 +140,24 @@ function logAdapter(logger: Logger, sessionId: string) { */ export class EventLogger { private spans = new Map(); - private transactions: Record = { - screenshotting: null, - generatePdf: null, + private transactions: Record = { + 'screenshot-pipeline': null, + 'generate-pdf': null, }; private sessionId: string; // identifier to track all logs from one screenshotting flow private logEvent: LogAdapter; - private timings: Partial> = {}; + private timings: Partial> = {}; constructor(private readonly logger: Logger, private readonly config: ConfigType) { this.sessionId = uuid.v4(); this.logEvent = logAdapter(logger.get('events'), this.sessionId); } - private startTiming(a: Actions) { + private startTiming(a: Actions | Transactions) { this.timings[a] = new Date(Date.now()); } - private sumScreenshotsByteLength = (byteLength: number, screenshot: Screenshot) => - byteLength + screenshot.data.byteLength; - /** * @returns Logger - original logger */ @@ -167,56 +166,31 @@ export class EventLogger { } /** - * Specific method for logging the beginning of the screenshotting pipeline + * General method for logging the beginning of any of this plugin's pipeline * * @returns {ScreenshottingEndFn} */ - public screenshottingTransaction(): ScreenshottingEndFn { - this.transactions.screenshotting = apm.startTransaction(Actions.SCREENSHOTTING, PLUGIN_ID); - this.startTiming(Actions.SCREENSHOTTING); - this.logEvent('screenshot pipeline', 'start', { action: Actions.SCREENSHOTTING }); - - return ({ metrics, results }) => { - const cpu = metrics?.cpu; - const memory = metrics?.memory; - const byteLength = results.reduce( - (totals, { screenshots }) => totals + screenshots.reduce(this.sumScreenshotsByteLength, 0), - 0 - ); + public startTransaction( + action: Transactions.SCREENSHOTTING | Transactions.PDF + ): TransactionEndFn { + this.transactions[action] = apm.startTransaction(action, PLUGIN_ID); + const transaction = this.transactions[action]; - this.transactions.screenshotting?.setLabel('cpu', cpu, false); - this.transactions.screenshotting?.setLabel('memory', memory, false); - this.transactions.screenshotting?.setLabel('byte-length', byteLength, false); - this.transactions.screenshotting?.end(); - this.logEvent( - 'screenshot pipeline', - 'complete', - { action: Actions.SCREENSHOTTING, byte_length: byteLength, cpu, memory }, - this.timings[Actions.SCREENSHOTTING] - ); - }; - } + this.startTiming(action); - /** - * Specific method for logging the beginning of the PDF generation pipeline - * - * @returns {GeneratePdfEndFn} - */ - public pdfTransaction(): GeneratePdfEndFn { - this.transactions.generatePdf = apm.startTransaction(Actions.PDF, PLUGIN_ID); - this.startTiming(Actions.PDF); - this.logEvent('pdf generation', 'start', { action: Actions.PDF }); - - return (action) => { - this.transactions.generatePdf?.setLabel('byte-length', action.byte_length_pdf, false); - this.transactions.generatePdf?.setLabel('pdf-pages', action.pdf_pages, false); - this.transactions.generatePdf?.end(); - this.logEvent( - 'pdf generation', - 'complete', - { ...action, action: Actions.PDF }, - this.timings[Actions.PDF] - ); + this.logEvent(action, 'start', { action }); + + return ({ labels }) => { + this.logEvent(action, 'complete', { action }); + + Object.entries(labels).forEach(([label]) => { + const labelField = label as keyof SimpleEvent; + const labelValue = labels[labelField]; + transaction?.setLabel(label, labelValue, false); + }); + transaction?.end(); + + this.logEvent(action, 'complete', { action }); }; } @@ -235,7 +209,7 @@ export class EventLogger { public log( message: string, action: Actions, - transaction: TransactionType, + transaction: Transactions, type: SpanTypes, metricsPre: Partial = {} ): LogEndFn { @@ -257,6 +231,22 @@ export class EventLogger { }; } + /** + * Helper function to calculate the byte length of a set of captured PNG images + */ + public getByteLengthFromCaptureResults(results: CaptureResult['results']) { + const totalByteLength = results.reduce( + (totals, { screenshots }) => + totals + + screenshots.reduce( + (byteLength: number, screenshot: Screenshot) => byteLength + screenshot.data.byteLength, + 0 + ), + 0 + ); + return totalByteLength; + } + /** * Helper function to create the "metricPre" data needed to log the start * of a screenshot capture event. @@ -277,7 +267,7 @@ export class EventLogger { * @param {Actions} action: The screenshotting action type * @returns void */ - public error(error: ErrorAction | string, action: Actions) { + public error(error: ErrorAction | string, action: Actions | Transactions) { const isError = typeof error === 'object'; const message = `Error: ${isError ? error.message : error}`; diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index e7f43e5feffe3..b4132ca96d253 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_ELEMENTATTRIBUTES } from './constants'; -import { Actions, EventLogger } from './event_logger'; +import { Actions, EventLogger, Transactions } from './event_logger'; export interface AttributesMap { [key: string]: string | null; @@ -43,7 +43,7 @@ export const getElementPositionAndAttributes = async ( const spanEnd = eventLogger.log( 'get element position data', Actions.GET_ELEMENT_POSITION_DATA, - 'screenshotting', + Transactions.SCREENSHOTTING, 'read' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts index fbaf9f20d191f..a9b8fef7287ab 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_GETNUMBEROFITEMS, CONTEXT_READMETADATA } from './constants'; -import { Actions, EventLogger } from './event_logger'; +import { Actions, EventLogger, Transactions } from './event_logger'; export const getNumberOfItems = async ( browser: HeadlessChromiumDriver, @@ -20,7 +20,7 @@ export const getNumberOfItems = async ( const spanEnd = eventLogger.log( 'get the number of visualization items on the page', Actions.GET_NUMBER_OF_ITEMS, - 'screenshotting', + Transactions.SCREENSHOTTING, 'read' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts index ac5f327f9ded5..354c9c4c70128 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import type { Layout } from '../layouts'; import { CONTEXT_GETRENDERERRORS } from './constants'; -import { Actions, EventLogger } from './event_logger'; +import { Actions, EventLogger, Transactions } from './event_logger'; export const getRenderErrors = async ( browser: HeadlessChromiumDriver, @@ -20,7 +20,7 @@ export const getRenderErrors = async ( const spanEnd = eventLogger.log( 'look for render errors', Actions.GET_RENDER_ERRORS, - 'screenshotting', + Transactions.SCREENSHOTTING, 'read' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index d072eb9e71cf4..50a8fa4ef2935 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -6,7 +6,7 @@ */ import type { HeadlessChromiumDriver } from '../browsers'; -import { Actions, EventLogger } from './event_logger'; +import { Actions, EventLogger, Transactions } from './event_logger'; import type { ElementsPositionAndAttribute } from './get_element_position_data'; export interface Screenshot { @@ -42,7 +42,7 @@ export const getScreenshots = async ( const endScreenshot = eventLogger.log( 'screenshot capture', Actions.GET_SCREENSHOT, - 'screenshotting', + Transactions.SCREENSHOTTING, 'read', eventLogger.getPixelsFromElementPosition(item.position) ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts index b5c746dcaee23..b41f009b3a499 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_GETTIMERANGE } from './constants'; -import { Actions, EventLogger } from './event_logger'; +import { Actions, EventLogger, Transactions } from './event_logger'; export const getTimeRange = async ( browser: HeadlessChromiumDriver, @@ -18,7 +18,7 @@ export const getTimeRange = async ( const spanEnd = eventLogger.log( 'looking for time range', Actions.GET_TIMERANGE, - 'screenshotting', + Transactions.SCREENSHOTTING, 'read' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/index.ts b/x-pack/plugins/screenshotting/server/screenshots/index.ts index 0788b6db8fefb..6e7211e0a6851 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/index.ts @@ -44,7 +44,7 @@ import { } from '../formats'; import type { Layout } from '../layouts'; import { createLayout } from '../layouts'; -import { Actions, EventLogger } from './event_logger'; +import { EventLogger, Transactions } from './event_logger'; import type { ScreenshotObservableOptions, ScreenshotObservableResult } from './observable'; import { ScreenshotObservableHandler, UrlOrUrlWithContext } from './observable'; import { Semaphore } from './semaphore'; @@ -150,7 +150,7 @@ export class Screenshots { screen.checkPageIsOpen(); // this fails the job if the browser has closed this.logger.error(error); - eventLogger.error(error, Actions.SCREENSHOTTING); + eventLogger.error(error, Transactions.SCREENSHOTTING); return of({ ...DEFAULT_SETUP_RESULT, error }); // allow failover screenshot capture }), takeUntil(unexpectedExit$), @@ -231,14 +231,21 @@ export class Screenshots { } const eventLogger = new EventLogger(this.logger, this.config); - const transactionEnd = eventLogger.screenshottingTransaction(); + const transactionEnd = eventLogger.startTransaction(Transactions.SCREENSHOTTING); const layout = this.createLayout(options); const captureOptions = this.getCaptureOptions(options); return this.captureScreenshots(eventLogger, layout, captureOptions).pipe( - tap((results) => { - transactionEnd(results); + tap(({ results, metrics }) => { + transactionEnd({ + labels: { + cpu: metrics?.cpu, + memory: metrics?.memory, + memory_mb: metrics?.memoryInMegabytes, + byte_length: eventLogger.getByteLengthFromCaptureResults(results), + }, + }); }), mergeMap((result) => { switch (options.format) { diff --git a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts index 54167a77b64cc..a87876de98599 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts @@ -10,7 +10,7 @@ import { promisify } from 'util'; import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_INJECTCSS } from './constants'; -import { Actions, EventLogger } from './event_logger'; +import { Actions, EventLogger, Transactions } from './event_logger'; const fsp = { readFile: promisify(fs.readFile) }; @@ -29,7 +29,7 @@ export const injectCustomCss = async ( const spanEnd = eventLogger.log( 'inject CSS into the page', Actions.INJECT_CSS, - 'screenshotting', + Transactions.SCREENSHOTTING, 'correction' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index 949705cd4d225..6d9764d821081 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -13,7 +13,7 @@ import type { Context, HeadlessChromiumDriver } from '../browsers'; import { DEFAULT_VIEWPORT, getChromiumDisconnectedError } from '../browsers'; import { ConfigType, durationToNumber as toNumber } from '../config'; import type { Layout } from '../layouts'; -import { Actions, EventLogger } from './event_logger'; +import { Actions, EventLogger, Transactions } from './event_logger'; import type { ElementsPositionAndAttribute } from './get_element_position_data'; import { getElementPositionAndAttributes } from './get_element_position_data'; import { getNumberOfItems } from './get_number_of_items'; @@ -197,7 +197,7 @@ export class ScreenshotObservableHandler { const spanEnd = this.eventLogger.log( 'get positions of visualization elements', Actions.GET_ELEMENT_POSITION_DATA, - 'screenshotting', + Transactions.SCREENSHOTTING, 'read' ); try { diff --git a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts index a252ede608b72..31d1affc33b9b 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts @@ -8,7 +8,7 @@ import type { Headers } from '@kbn/core/server'; import type { Context, HeadlessChromiumDriver } from '../browsers'; import { DEFAULT_PAGELOAD_SELECTOR } from './constants'; -import { Actions, EventLogger } from './event_logger'; +import { Actions, EventLogger, Transactions } from './event_logger'; export const openUrl = async ( browser: HeadlessChromiumDriver, @@ -20,7 +20,12 @@ export const openUrl = async ( headers: Headers ): Promise => { const { kbnLogger } = eventLogger; - const spanEnd = eventLogger.log('open url', Actions.OPEN_URL, 'screenshotting', 'wait'); + const spanEnd = eventLogger.log( + 'open url', + Actions.OPEN_URL, + Transactions.SCREENSHOTTING, + 'wait' + ); // If we're moving to another page in the app, we'll want to wait for the app to tell us // it's loaded the next page. diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts index 497a6c84fe3a9..810d2bfc47c65 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_WAITFORRENDER } from './constants'; -import { Actions, EventLogger } from './event_logger'; +import { Actions, EventLogger, Transactions } from './event_logger'; export const waitForRenderComplete = async ( browser: HeadlessChromiumDriver, @@ -19,7 +19,7 @@ export const waitForRenderComplete = async ( const spanEnd = eventLogger.log( 'wait for render complete', Actions.WAIT_RENDER, - 'screenshotting', + Transactions.SCREENSHOTTING, 'wait' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts index 676467a885cfd..9a071de9d14c4 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_WAITFORELEMENTSTOBEINDOM } from './constants'; -import { Actions, EventLogger } from './event_logger'; +import { Actions, EventLogger, Transactions } from './event_logger'; interface CompletedItemsCountParameters { context: string; @@ -45,7 +45,7 @@ export const waitForVisualizations = async ( const spanEnd = eventLogger.log( 'waiting for each visualization to complete rendering', Actions.WAIT_VISUALIZATIONS, - 'screenshotting', + Transactions.SCREENSHOTTING, 'wait' ); From ec1ea1552d03ee769ac816c43580a4f6a90e2fd1 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Tue, 3 May 2022 15:28:08 -0700 Subject: [PATCH 28/28] shortcut methods for screenshot/pdf event log --- .../server/formats/pdf/pdf_maker/index.ts | 10 +---- .../screenshots/event_logger/index.test.ts | 37 +++++++++------- .../server/screenshots/event_logger/index.ts | 44 ++++++++++++++----- .../screenshots/get_element_position_data.ts | 5 +-- .../server/screenshots/get_number_of_items.ts | 5 +-- .../server/screenshots/get_render_errors.ts | 5 +-- .../server/screenshots/get_screenshots.ts | 5 +-- .../server/screenshots/get_time_range.ts | 5 +-- .../server/screenshots/index.ts | 2 +- .../server/screenshots/inject_css.ts | 5 +-- .../server/screenshots/observable.ts | 5 +-- .../server/screenshots/open_url.ts | 9 +--- .../server/screenshots/wait_for_render.ts | 5 +-- .../screenshots/wait_for_visualizations.ts | 5 +-- 14 files changed, 77 insertions(+), 70 deletions(-) diff --git a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts index 5a71cf5047247..280b9173c7920 100644 --- a/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts +++ b/x-pack/plugins/screenshotting/server/formats/pdf/pdf_maker/index.ts @@ -40,10 +40,9 @@ export async function pngsToPdf({ } results.forEach((result) => { result.screenshots.forEach((png) => { - const spanEnd = eventLogger.log( + const spanEnd = eventLogger.logPdfEvent( 'add image to PDF file', Actions.ADD_IMAGE, - Transactions.PDF, 'output' ); pdfMaker?.addImage(png.data, { @@ -54,12 +53,7 @@ export async function pngsToPdf({ }); }); - const spanEnd = eventLogger.log( - 'compile PDF file', - Actions.COMPILE, - Transactions.PDF, - 'output' - ); + const spanEnd = eventLogger.logPdfEvent('compile PDF file', Actions.COMPILE, 'output'); buffer = await pdfMaker.generate(); spanEnd(); diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts index 2fcc12738455a..3a20c404ff497 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.test.ts @@ -38,29 +38,32 @@ describe('Event Logger', () => { it('creates logs for the events and includes durations and event payload data', () => { const screenshottingEnd = eventLogger.startTransaction(Transactions.SCREENSHOTTING); - const openUrlEnd = eventLogger.log( + const openUrlEnd = eventLogger.logScreenshottingEvent( 'open the url to the Kibana application', Actions.OPEN_URL, - Transactions.SCREENSHOTTING, 'wait' ); openUrlEnd(); - const getElementPositionsEnd = eventLogger.log( + const getElementPositionsEnd = eventLogger.logScreenshottingEvent( 'scan the page to find the boundaries of visualization elements', Actions.GET_ELEMENT_POSITION_DATA, - Transactions.SCREENSHOTTING, 'wait' ); getElementPositionsEnd(); screenshottingEnd({ - labels: { cpu: 12, cpu_percentage: 0, memory: 450789, memory_mb: 449 }, + labels: { + cpu: 12, + cpu_percentage: 0, + memory: 450789, + memory_mb: 449, + byte_length: 14000, + }, }); const pdfEnd = eventLogger.startTransaction(Transactions.PDF); - const addImageEnd = eventLogger.log( + const addImageEnd = eventLogger.logPdfEvent( 'add image to the PDF file', Actions.ADD_IMAGE, - Transactions.PDF, 'output' ); addImageEnd(); @@ -72,11 +75,12 @@ describe('Event Logger', () => { screenshotting: data?.kibana?.screenshotting, })); + expect(logs.length).toBe(10); expect(logs).toMatchInlineSnapshot(` Array [ Object { "duration": undefined, - "message": "starting: screenshot pipeline", + "message": "starting: screenshot-pipeline", "screenshotting": Object { "action": "screenshot-pipeline-start", "session_id": "NEW_UUID", @@ -116,18 +120,20 @@ describe('Event Logger', () => { }, Object { "duration": 20000, - "message": "completed: screenshot pipeline", + "message": "completed: screenshot-pipeline", "screenshotting": Object { "action": "screenshot-pipeline-complete", - "byte_length": 0, + "byte_length": 14000, "cpu": 12, + "cpu_percentage": 0, "memory": 450789, + "memory_mb": 449, "session_id": "NEW_UUID", }, }, Object { "duration": undefined, - "message": "starting: pdf generation", + "message": "starting: generate-pdf", "screenshotting": Object { "action": "generate-pdf-start", "session_id": "NEW_UUID", @@ -151,7 +157,7 @@ describe('Event Logger', () => { }, Object { "duration": 27000, - "message": "completed: pdf generation", + "message": "completed: generate-pdf", "screenshotting": Object { "action": "generate-pdf-complete", "byte_length_pdf": 6666, @@ -168,10 +174,9 @@ describe('Event Logger', () => { boundingClientRect: { width: 1350, height: 2000 }, scroll: {}, } as ElementPosition; - const endScreenshot = eventLogger.log( + const endScreenshot = eventLogger.logScreenshottingEvent( 'screenshot capture test', Actions.GET_SCREENSHOT, - Transactions.SCREENSHOTTING, 'read', eventLogger.getPixelsFromElementPosition(elementPosition) ); @@ -210,7 +215,7 @@ describe('Event Logger', () => { it('creates helpful error logs', () => { eventLogger.startTransaction(Transactions.SCREENSHOTTING); - eventLogger.log('opening the url', Actions.OPEN_URL, Transactions.SCREENSHOTTING, 'wait'); + eventLogger.logScreenshottingEvent('opening the url', Actions.OPEN_URL, 'wait'); eventLogger.error(new Error('Something erroneous happened'), Transactions.SCREENSHOTTING); const logData = logSpy.mock.calls.map(([message, data]) => ({ @@ -223,7 +228,7 @@ describe('Event Logger', () => { Array [ Object { "error": undefined, - "message": "starting: screenshot pipeline", + "message": "starting: screenshot-pipeline", "screenshotting": Object { "action": "screenshot-pipeline-start", "session_id": "NEW_UUID", diff --git a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts index d017b4e82c8fc..033fb24c80685 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/event_logger/index.ts @@ -84,7 +84,7 @@ type LogAdapter = ( startTime?: Date | undefined ) => void; -type Labels = Record; +type Labels = Record; type TransactionEndFn = (args: { labels: Partial }) => void; type LogEndFn = (metricData?: Partial) => void; @@ -177,25 +177,21 @@ export class EventLogger { const transaction = this.transactions[action]; this.startTiming(action); - this.logEvent(action, 'start', { action }); return ({ labels }) => { - this.logEvent(action, 'complete', { action }); - Object.entries(labels).forEach(([label]) => { const labelField = label as keyof SimpleEvent; const labelValue = labels[labelField]; transaction?.setLabel(label, labelValue, false); }); + transaction?.end(); - this.logEvent(action, 'complete', { action }); + this.logEvent(action, 'complete', { ...labels, action }, this.timings[action]); }; } - // General method for spans - /** * General event logging function * @@ -209,9 +205,9 @@ export class EventLogger { public log( message: string, action: Actions, - transaction: Transactions, type: SpanTypes, - metricsPre: Partial = {} + metricsPre: Partial = {}, + transaction: Transactions ): LogEndFn { const txn = this.transactions[transaction]; const span = txn?.startSpan(action, type); @@ -231,10 +227,36 @@ export class EventLogger { }; } + /** + * Logging helper for screenshotting events + */ + public logScreenshottingEvent( + message: string, + action: Actions, + type: SpanTypes, + metricsPre: Partial = {} + ) { + return this.log(message, action, type, metricsPre, Transactions.SCREENSHOTTING); + } + + /** + * Logging helper for screenshotting events + */ + public logPdfEvent( + message: string, + action: Actions, + type: SpanTypes, + metricsPre: Partial = {} + ) { + return this.log(message, action, type, metricsPre, Transactions.PDF); + } + /** * Helper function to calculate the byte length of a set of captured PNG images */ - public getByteLengthFromCaptureResults(results: CaptureResult['results']) { + public getByteLengthFromCaptureResults( + results: CaptureResult['results'] + ): Pick { const totalByteLength = results.reduce( (totals, { screenshots }) => totals + @@ -244,7 +266,7 @@ export class EventLogger { ), 0 ); - return totalByteLength; + return { byte_length: totalByteLength }; } /** diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts index b4132ca96d253..5018701ce2411 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_element_position_data.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_ELEMENTATTRIBUTES } from './constants'; -import { Actions, EventLogger, Transactions } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; export interface AttributesMap { [key: string]: string | null; @@ -40,10 +40,9 @@ export const getElementPositionAndAttributes = async ( ): Promise => { const { kbnLogger } = eventLogger; - const spanEnd = eventLogger.log( + const spanEnd = eventLogger.logScreenshottingEvent( 'get element position data', Actions.GET_ELEMENT_POSITION_DATA, - Transactions.SCREENSHOTTING, 'read' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts index a9b8fef7287ab..0e4da2fe5cf6a 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_number_of_items.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_GETNUMBEROFITEMS, CONTEXT_READMETADATA } from './constants'; -import { Actions, EventLogger, Transactions } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; export const getNumberOfItems = async ( browser: HeadlessChromiumDriver, @@ -17,10 +17,9 @@ export const getNumberOfItems = async ( layout: Layout ): Promise => { const { kbnLogger } = eventLogger; - const spanEnd = eventLogger.log( + const spanEnd = eventLogger.logScreenshottingEvent( 'get the number of visualization items on the page', Actions.GET_NUMBER_OF_ITEMS, - Transactions.SCREENSHOTTING, 'read' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts index 354c9c4c70128..44b92ceddbc8d 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_render_errors.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import type { Layout } from '../layouts'; import { CONTEXT_GETRENDERERRORS } from './constants'; -import { Actions, EventLogger, Transactions } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; export const getRenderErrors = async ( browser: HeadlessChromiumDriver, @@ -17,10 +17,9 @@ export const getRenderErrors = async ( ): Promise => { const { kbnLogger } = eventLogger; - const spanEnd = eventLogger.log( + const spanEnd = eventLogger.logScreenshottingEvent( 'look for render errors', Actions.GET_RENDER_ERRORS, - Transactions.SCREENSHOTTING, 'read' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts index 50a8fa4ef2935..f157649bbb848 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_screenshots.ts @@ -6,7 +6,7 @@ */ import type { HeadlessChromiumDriver } from '../browsers'; -import { Actions, EventLogger, Transactions } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; import type { ElementsPositionAndAttribute } from './get_element_position_data'; export interface Screenshot { @@ -39,10 +39,9 @@ export const getScreenshots = async ( try { for (let i = 0; i < elementsPositionAndAttributes.length; i++) { const item = elementsPositionAndAttributes[i]; - const endScreenshot = eventLogger.log( + const endScreenshot = eventLogger.logScreenshottingEvent( 'screenshot capture', Actions.GET_SCREENSHOT, - Transactions.SCREENSHOTTING, 'read', eventLogger.getPixelsFromElementPosition(item.position) ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts index b41f009b3a499..f9272fd27ac95 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/get_time_range.ts @@ -8,17 +8,16 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_GETTIMERANGE } from './constants'; -import { Actions, EventLogger, Transactions } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; export const getTimeRange = async ( browser: HeadlessChromiumDriver, eventLogger: EventLogger, layout: Layout ): Promise => { - const spanEnd = eventLogger.log( + const spanEnd = eventLogger.logScreenshottingEvent( 'looking for time range', Actions.GET_TIMERANGE, - Transactions.SCREENSHOTTING, 'read' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/index.ts b/x-pack/plugins/screenshotting/server/screenshots/index.ts index 6e7211e0a6851..33404bb5fadc2 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/index.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/index.ts @@ -243,7 +243,7 @@ export class Screenshots { cpu: metrics?.cpu, memory: metrics?.memory, memory_mb: metrics?.memoryInMegabytes, - byte_length: eventLogger.getByteLengthFromCaptureResults(results), + ...eventLogger.getByteLengthFromCaptureResults(results), }, }); }), diff --git a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts index a87876de98599..41426e893ce58 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/inject_css.ts @@ -10,7 +10,7 @@ import { promisify } from 'util'; import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_INJECTCSS } from './constants'; -import { Actions, EventLogger, Transactions } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; const fsp = { readFile: promisify(fs.readFile) }; @@ -26,10 +26,9 @@ export const injectCustomCss = async ( const { kbnLogger } = eventLogger; - const spanEnd = eventLogger.log( + const spanEnd = eventLogger.logScreenshottingEvent( 'inject CSS into the page', Actions.INJECT_CSS, - Transactions.SCREENSHOTTING, 'correction' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/observable.ts b/x-pack/plugins/screenshotting/server/screenshots/observable.ts index 6d9764d821081..5048d3f0a3be6 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/observable.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/observable.ts @@ -13,7 +13,7 @@ import type { Context, HeadlessChromiumDriver } from '../browsers'; import { DEFAULT_VIEWPORT, getChromiumDisconnectedError } from '../browsers'; import { ConfigType, durationToNumber as toNumber } from '../config'; import type { Layout } from '../layouts'; -import { Actions, EventLogger, Transactions } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; import type { ElementsPositionAndAttribute } from './get_element_position_data'; import { getElementPositionAndAttributes } from './get_element_position_data'; import { getNumberOfItems } from './get_number_of_items'; @@ -194,10 +194,9 @@ export class ScreenshotObservableHandler { // allows for them to be displayed properly in many cases await injectCustomCss(driver, eventLogger, layout); - const spanEnd = this.eventLogger.log( + const spanEnd = this.eventLogger.logScreenshottingEvent( 'get positions of visualization elements', Actions.GET_ELEMENT_POSITION_DATA, - Transactions.SCREENSHOTTING, 'read' ); try { diff --git a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts index 31d1affc33b9b..bdf8c678eb1d2 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/open_url.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/open_url.ts @@ -8,7 +8,7 @@ import type { Headers } from '@kbn/core/server'; import type { Context, HeadlessChromiumDriver } from '../browsers'; import { DEFAULT_PAGELOAD_SELECTOR } from './constants'; -import { Actions, EventLogger, Transactions } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; export const openUrl = async ( browser: HeadlessChromiumDriver, @@ -20,12 +20,7 @@ export const openUrl = async ( headers: Headers ): Promise => { const { kbnLogger } = eventLogger; - const spanEnd = eventLogger.log( - 'open url', - Actions.OPEN_URL, - Transactions.SCREENSHOTTING, - 'wait' - ); + const spanEnd = eventLogger.logScreenshottingEvent('open url', Actions.OPEN_URL, 'wait'); // If we're moving to another page in the app, we'll want to wait for the app to tell us // it's loaded the next page. diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts index 810d2bfc47c65..8cf8174be152f 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_render.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_WAITFORRENDER } from './constants'; -import { Actions, EventLogger, Transactions } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; export const waitForRenderComplete = async ( browser: HeadlessChromiumDriver, @@ -16,10 +16,9 @@ export const waitForRenderComplete = async ( loadDelay: number, layout: Layout ) => { - const spanEnd = eventLogger.log( + const spanEnd = eventLogger.logScreenshottingEvent( 'wait for render complete', Actions.WAIT_RENDER, - Transactions.SCREENSHOTTING, 'wait' ); diff --git a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts index 9a071de9d14c4..cf49fbe7dc798 100644 --- a/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts +++ b/x-pack/plugins/screenshotting/server/screenshots/wait_for_visualizations.ts @@ -8,7 +8,7 @@ import type { HeadlessChromiumDriver } from '../browsers'; import { Layout } from '../layouts'; import { CONTEXT_WAITFORELEMENTSTOBEINDOM } from './constants'; -import { Actions, EventLogger, Transactions } from './event_logger'; +import { Actions, EventLogger } from './event_logger'; interface CompletedItemsCountParameters { context: string; @@ -42,10 +42,9 @@ export const waitForVisualizations = async ( layout: Layout ): Promise => { const { kbnLogger } = eventLogger; - const spanEnd = eventLogger.log( + const spanEnd = eventLogger.logScreenshottingEvent( 'waiting for each visualization to complete rendering', Actions.WAIT_VISUALIZATIONS, - Transactions.SCREENSHOTTING, 'wait' );