Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Reporting] Remove Chome stdout/stderr observables, Add Browser Logger observable #44359

Merged
merged 5 commits into from
Sep 5, 2019
Merged

[Reporting] Remove Chome stdout/stderr observables, Add Browser Logger observable #44359

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
82b17d5
Add browserLogger$, processLogger$
tsullivan Aug 28, 2019
570f411
clean up messy logs being forwarded
tsullivan Aug 29, 2019
041d864
Merge branch 'master' of github.com:elastic/kibana into reporting/fix…
tsullivan Aug 30, 2019
121e87e
Merge branch 'master' into reporting/fix-browser-console-logging
tsullivan Sep 3, 2019
1377459
Merge branch 'master' into reporting/fix-browser-console-logging
tsullivan Sep 5, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 1 addition & 7 deletions x-pack/legacy/plugins/reporting/export_types/common/lib/screenshots/index.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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),
Expand Down
184 changes: 86 additions & 98 deletions x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand All @@ -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;
Expand Down Expand Up @@ -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);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This fixes an unrelated problem where an error object was getting concatenated with a string, making it unreadable

logger.warning(`See Chromium's log output at "${getChromeLogLocation(this.binaryPath)}"`);
return null;
});
Expand All @@ -87,8 +90,6 @@ export class HeadlessChromiumDriverFactory {
browserTimezone: string;
}): Rx.Observable<{
driver$: Rx.Observable<HeadlessChromiumDriver>;
consoleMessage$: Rx.Observable<string>;
message$: Rx.Observable<string>;
exit$: Rx.Observable<never>;
}> {
return Rx.Observable.create(async (observer: InnerSubscriber<any, any>) => {
Expand Down Expand Up @@ -157,109 +158,96 @@ 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$);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Removing this code as it does not work with the puppeteer driver. I believe this was written at a time when we launched Chromium directly, without a helper. As of now, we no longer have a way to scan the browser's stdin / stderr as a stream.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe this only works if you use dumpio in puppeteer launch: https://pptr.dev/#?product=Puppeteer&version=v1.19.0&show=api-puppeteerlaunchoptions. We don't expose an option to do this, so I'm cool with removing this

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same here. As we have explored using dumpio before and found that it doesn't provide a stream of helpful info for us.


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}]`
);
}
});
});
});
}

getBrowserLogger(page: Page): Rx.Observable<ConsoleMessage> {
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.text(), [line.type(), 'headless-browser-console']);
}
})
);
}

getProcessLogger(browser: Browser): Rx.Observable<string> {
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<string> = 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<never> {
const pageError$: Rx.Observable<never> = Rx.fromEvent(page, 'error').pipe(
mergeMap((err: Error) => Rx.throwError(err))
);

const uncaughtExceptionPageError$: Rx.Observable<never> = Rx.fromEvent(page, 'pageerror').pipe(
mergeMap((err: Error) => Rx.throwError(err))
);

const pageRequestFailed$: Rx.Observable<never> = 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$
);
}
}
14 changes: 9 additions & 5 deletions x-pack/legacy/plugins/reporting/server/lib/level_logger.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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[];
Expand All @@ -30,20 +34,20 @@ 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[] = []) {
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() {
Expand Down