From 82b17d575c503f0fff7e7de9b07b64f6858dc0c4 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Wed, 28 Aug 2019 14:57:16 -0700 Subject: [PATCH 1/2] Add browserLogger$, processLogger$ Remove handling of nssError$, fontError$, noUsableSandbox$ --- .../common/lib/screenshots/index.ts | 8 +- .../browsers/chromium/driver_factory/index.ts | 184 ++++++++---------- .../reporting/server/lib/level_logger.ts | 4 +- 3 files changed, 89 insertions(+), 107 deletions(-) diff --git a/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/index.ts b/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/index.ts index 9769e5abde670d..125baa314e07ef 100644 --- a/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/index.ts +++ b/x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/index.ts @@ -45,13 +45,7 @@ export function screenshotsObservableFactory(server: KbnServer) { }); return create$.pipe( - mergeMap(({ driver$, exit$, message$, consoleMessage$ }) => { - message$.subscribe((line: string) => { - logger.debug(line, ['browser']); - }); - consoleMessage$.subscribe((line: string) => { - logger.debug(line, ['browserConsole']); - }); + mergeMap(({ driver$, exit$ }) => { const screenshot$ = driver$.pipe( mergeMap( (browser: HeadlessBrowser) => openUrl(browser, url, conditionalHeaders, logger), diff --git a/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts b/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts index 6df8b37dd1d305..8dc67c779473cd 100644 --- a/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts +++ b/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts @@ -6,10 +6,16 @@ import fs from 'fs'; import os from 'os'; import path from 'path'; -import { Browser, Page, LaunchOptions } from 'puppeteer'; +import { + Browser, + Page, + LaunchOptions, + ConsoleMessage, + Request as PuppeteerRequest, +} from 'puppeteer'; import rimraf from 'rimraf'; import * as Rx from 'rxjs'; -import { map, share, mergeMap, filter, partition, ignoreElements, tap } from 'rxjs/operators'; +import { ignoreElements, mergeMap, tap } from 'rxjs/operators'; import { InnerSubscriber } from 'rxjs/internal/InnerSubscriber'; import { puppeteerLaunch } from '../puppeteer'; @@ -25,10 +31,6 @@ interface IBrowserConfig { [key: string]: any; } -const compactWhitespace = (str: string) => { - return str.replace(/\s+/, ' '); -}; - export class HeadlessChromiumDriverFactory { private binaryPath: binaryPath; private logger: Logger; @@ -71,9 +73,10 @@ export class HeadlessChromiumDriverFactory { TZ: browserTimezone, }, } as LaunchOptions).catch((error: Error) => { - logger.warning( - `The Reporting plugin encountered issues launching Chromium in a self-test. You may have trouble generating reports: [${error}]` + logger.error( + `The Reporting plugin encountered issues launching Chromium in a self-test. You may have trouble generating reports.` ); + logger.error(error); logger.warning(`See Chromium's log output at "${getChromeLogLocation(this.binaryPath)}"`); return null; }); @@ -87,8 +90,6 @@ export class HeadlessChromiumDriverFactory { browserTimezone: string; }): Rx.Observable<{ driver$: Rx.Observable; - consoleMessage$: Rx.Observable; - message$: Rx.Observable; exit$: Rx.Observable; }> { return Rx.Observable.create(async (observer: InnerSubscriber) => { @@ -157,104 +158,24 @@ export class HeadlessChromiumDriverFactory { .subscribe(observer) ); - // Register with a few useful puppeteer event handlers: - // https://pptr.dev/#?product=Puppeteer&version=v1.10.0&show=api-event-error - // https://github.com/GoogleChrome/puppeteer/blob/master/docs/api.md#class-page - - const stderr$ = Rx.fromEvent(page as NodeJS.EventEmitter, 'console').pipe( - filter((line: any) => line._type === 'error'), - map((line: any) => line._text), - share() - ); - - const [consoleMessage$, message$] = partition( - (msg: string) => !!msg.match(/\[\d+\/\d+.\d+:\w+:CONSOLE\(\d+\)\]/) - )(stderr$); - - const driver$ = Rx.of( - new HeadlessChromiumDriver(page, { inspect: this.browserConfig.inspect }) - ); + // taps the browser log streams and combine them to Kibana logs + this.getBrowserLogger(page).subscribe(); + this.getProcessLogger(browser).subscribe(); - const processError$ = Rx.fromEvent(page, 'error').pipe( - mergeMap(err => Rx.throwError(new Error(`Unable to spawn Chromium: [${err}]`))) - ); + const driver$ = Rx.of(new HeadlessChromiumDriver(page, { inspect: this.browserConfig.inspect })); // prettier-ignore - const processPageError$ = Rx.fromEvent(page, 'pageerror').pipe( - mergeMap(err => Rx.throwError(new Error(`Uncaught exception within the page: [${err}]`))) - ); + const exit$ = this.getPageExit(browser, page); - const processRequestFailed$ = Rx.fromEvent(page, 'requestfailed').pipe( - mergeMap((req: any) => { - const failure = req.failure && req.failure(); - if (failure) { - return Rx.throwError( - new Error(`Request to [${req.url()}] failed! [${failure.errorText}]`) - ); - } - return Rx.throwError(new Error(`Unknown failure! [${JSON.stringify(req)}]`)); - }) - ); - - const processExit$ = Rx.fromEvent(browser, 'disconnected').pipe( - mergeMap(code => - Rx.throwError(new Error(`Chromium exited with: [${JSON.stringify({ code })}]`)) - ) - ); - - const nssError$ = message$.pipe( - filter((line: string) => line.includes('error while loading shared libraries: libnss3.so')), - mergeMap(() => Rx.throwError(new Error(`You must install nss for Reporting to work`))) - ); - - const fontError$ = message$.pipe( - filter((line: string) => - line.includes('Check failed: InitDefaultFont(). Could not find the default font') - ), - mergeMap(() => - Rx.throwError(new Error('You must install freetype and ttf-font for Reporting to work')) - ) - ); + observer.next({ driver$, exit$ }); - const noUsableSandbox$ = message$.pipe( - filter((line: string) => line.includes('No usable sandbox! Update your kernel')), - mergeMap(() => - Rx.throwError( - new Error( - compactWhitespace(` - Unable to use Chromium sandbox. This can be disabled at your own risk with - 'xpack.reporting.capture.browser.chromium.disableSandbox' - `) - ) - ) - ) - ); - - const exit$ = Rx.merge( - processError$, - processPageError$, - processRequestFailed$, - processExit$, - nssError$, - fontError$, - noUsableSandbox$ - ); - - observer.next({ - driver$, - consoleMessage$, - message$, - exit$, - }); - - const factoryLogger = this.logger.clone(['chromium-driver-factory']); // unsubscribe logic makes a best-effort attempt to delete the user data directory used by chromium observer.add(() => { - factoryLogger.debug(`deleting chromium user data directory at [${userDataDir}]`); + this.logger.debug(`deleting chromium user data directory at [${userDataDir}]`); // the unsubscribe function isn't `async` so we're going to make our best effort at // deleting the userDataDir and if it fails log an error. rimraf(userDataDir, err => { if (err) { - return factoryLogger.error( + return this.logger.error( `error deleting user data directory at [${userDataDir}]: [${err}]` ); } @@ -262,4 +183,71 @@ export class HeadlessChromiumDriverFactory { }); }); } + + getBrowserLogger(page: Page): Rx.Observable { + return Rx.fromEvent(page as NodeJS.EventEmitter, 'console').pipe( + tap((line: ConsoleMessage) => { + if (line.type() === 'error') { + this.logger.error(line.text(), ['headless-browser-console']); + } else { + this.logger.debug(`[${line.type()}] ${line.text()}`, ['headless-browser-console']); + } + }) + ); + } + + getProcessLogger(browser: Browser): Rx.Observable { + const childProcess = browser.process(); + // NOTE: The browser driver can not observe stdout and stderr of the child process + // Puppeteer doesn't give a handle to the original ChildProcess object + // See https://github.com/GoogleChrome/puppeteer/issues/1292#issuecomment-521470627 + + // just log closing of the process + const processClose$: Rx.Observable = Rx.fromEvent(childProcess, 'close').pipe( + tap(() => { + this.logger.debug('child process closed', ['headless-browser-process']); + }) + ); + + return processClose$; // ideally, this would also merge with observers for stdout and stderr + } + + getPageExit(browser: Browser, page: Page): Rx.Observable { + const pageError$: Rx.Observable = Rx.fromEvent(page, 'error').pipe( + mergeMap((err: Error) => Rx.throwError(err)) + ); + + const uncaughtExceptionPageError$: Rx.Observable = Rx.fromEvent(page, 'pageerror').pipe( + mergeMap((err: Error) => Rx.throwError(err)) + ); + + const pageRequestFailed$: Rx.Observable = Rx.fromEvent(page, 'requestfailed').pipe( + mergeMap((req: PuppeteerRequest) => { + const failure = req.failure && req.failure(); + if (failure) { + return Rx.throwError( + new Error(`Request to [${req.url()}] failed! [${failure.errorText}]`) + ); + } + return Rx.throwError(new Error(`Unknown failure!`)); + }) + ); + + const browserDisconnect$ = Rx.fromEvent(browser, 'disconnected').pipe( + mergeMap(() => + Rx.throwError( + new Error( + `Puppeteer was disconnected from the Chromium instance! Chromium has closed or crashed.` + ) + ) + ) + ); + + return Rx.merge( + pageError$, + uncaughtExceptionPageError$, + pageRequestFailed$, + browserDisconnect$ + ); + } } diff --git a/x-pack/legacy/plugins/reporting/server/lib/level_logger.ts b/x-pack/legacy/plugins/reporting/server/lib/level_logger.ts index 868ae163b15fcc..6245d793fdc223 100644 --- a/x-pack/legacy/plugins/reporting/server/lib/level_logger.ts +++ b/x-pack/legacy/plugins/reporting/server/lib/level_logger.ts @@ -30,8 +30,8 @@ export class LevelLogger { this.warn = this.warning.bind(this); } - public error(msg: string, tags: string[] = []) { - this._logger([...this._tags, ...tags, 'error'], msg); + public error(err: string | Error, tags: string[] = []) { + this._logger([...this._tags, ...tags, 'error'], err); } public warning(msg: string, tags: string[] = []) { From 570f4110643e1c74fa962c3f0c9d640733f619f4 Mon Sep 17 00:00:00 2001 From: Timothy Sullivan Date: Thu, 29 Aug 2019 00:48:02 -0700 Subject: [PATCH 2/2] clean up messy logs being forwarded --- .../server/browsers/chromium/driver_factory/index.ts | 2 +- .../plugins/reporting/server/lib/level_logger.ts | 10 +++++++--- 2 files changed, 8 insertions(+), 4 deletions(-) diff --git a/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts b/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts index 8dc67c779473cd..01454f2a9fae0d 100644 --- a/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts +++ b/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts @@ -190,7 +190,7 @@ export class HeadlessChromiumDriverFactory { if (line.type() === 'error') { this.logger.error(line.text(), ['headless-browser-console']); } else { - this.logger.debug(`[${line.type()}] ${line.text()}`, ['headless-browser-console']); + this.logger.debug(line.text(), [line.type(), 'headless-browser-console']); } }) ); diff --git a/x-pack/legacy/plugins/reporting/server/lib/level_logger.ts b/x-pack/legacy/plugins/reporting/server/lib/level_logger.ts index 6245d793fdc223..810ccf253943cc 100644 --- a/x-pack/legacy/plugins/reporting/server/lib/level_logger.ts +++ b/x-pack/legacy/plugins/reporting/server/lib/level_logger.ts @@ -6,6 +6,10 @@ type ServerLog = (tags: string[], msg: string) => void; +const trimStr = (toTrim: string) => { + return typeof toTrim === 'string' ? toTrim.trim() : toTrim; +}; + export class LevelLogger { private _logger: any; private _tags: string[]; @@ -35,15 +39,15 @@ export class LevelLogger { } public warning(msg: string, tags: string[] = []) { - this._logger([...this._tags, ...tags, 'warning'], msg); + this._logger([...this._tags, ...tags, 'warning'], trimStr(msg)); } public debug(msg: string, tags: string[] = []) { - this._logger([...this._tags, ...tags, 'debug'], msg); + this._logger([...this._tags, ...tags, 'debug'], trimStr(msg)); } public info(msg: string, tags: string[] = []) { - this._logger([...this._tags, ...tags, 'info'], msg); + this._logger([...this._tags, ...tags, 'info'], trimStr(msg)); } public get isVerbose() {