[services/remote] print Firefox console logs in stdout (#46700) (#47532)

* [services/remote] print Firefox console logs in stdout

* [ftr/firefox] setup a socket for firefox to write stdout to

* remove unused imports

* unsubscribe from polling logs on cleanup

* tear down more completely on cleanup

test/functional/services/browser.ts

@@ -18,40 +18,27 @@
  */
 
 import { cloneDeep } from 'lodash';
-import { logging, Key, Origin } from 'selenium-webdriver';
+import { Key, Origin } from 'selenium-webdriver';
 // @ts-ignore internal modules are not typed
 import { LegacyActionSequence } from 'selenium-webdriver/lib/actions';
-import { takeUntil } from 'rxjs/operators';
 
 import { modifyUrl } from '../../../src/core/utils';
 import { WebElementWrapper } from './lib/web_element_wrapper';
 import { FtrProviderContext } from '../ftr_provider_context';
 import { Browsers } from './remote/browsers';
-import { pollForLogEntry$ } from './remote/poll_for_log_entry';
 
 export async function BrowserProvider({ getService }: FtrProviderContext) {
   const log = getService('log');
-  const config = getService('config');
-  const lifecycle = getService('lifecycle');
-  const { driver, browserType } = await getService('__webdriver__').init();
+  const { driver, browserType, consoleLog$ } = await getService('__webdriver__').init();
+
+  consoleLog$.subscribe(({ message, level }) => {
+    log[level === 'SEVERE' || level === 'error' ? 'error' : 'debug'](
+      `browser[${level}] ${message}`
+    );
+  });
 
   const isW3CEnabled = (driver as any).executor_.w3c === true;
 
-  if (browserType === Browsers.Chrome) {
-    // The logs endpoint has not been defined in W3C Spec browsers other than Chrome don't have access to this endpoint.
-    // See: https://github.com/w3c/webdriver/issues/406
-    // See: https://w3c.github.io/webdriver/#endpoints
-
-    pollForLogEntry$(driver, logging.Type.BROWSER, config.get('browser.logPollingMs'))
-      .pipe(takeUntil(lifecycle.cleanup$))
-      .subscribe({
-        next({ message, level: { name: level } }) {
-          const msg = message.replace(/\\n/g, '\n');
-          log[level === 'SEVERE' ? 'error' : 'debug'](`browser[${level}] ${msg}`);
-        },
-      });
-  }
-
   return new (class BrowserService {
     /**
      * Keyboard events

test/functional/services/remote/create_stdout_stream.ts

@@ -0,0 +1,92 @@
+/*
+ * Licensed to Elasticsearch B.V. under one or more contributor
+ * license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright
+ * ownership. Elasticsearch B.V. licenses this file to you under
+ * the Apache License, Version 2.0 (the "License"); you may
+ * not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *    http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+
+import Net from 'net';
+
+import * as Rx from 'rxjs';
+import { map, takeUntil, take } from 'rxjs/operators';
+
+export async function createStdoutSocket() {
+  const chunk$ = new Rx.Subject<Buffer>();
+  const cleanup$ = new Rx.ReplaySubject(1);
+
+  const server = Net.createServer();
+  server.on('connection', socket => {
+    const data$ = Rx.fromEvent<Buffer>(socket, 'data');
+    const end$ = Rx.fromEvent(socket, 'end');
+    const error$ = Rx.fromEvent<Error>(socket, 'error');
+
+    Rx.merge(data$, error$)
+      .pipe(takeUntil(Rx.merge(end$, cleanup$)))
+      .subscribe({
+        next(chunkOrError) {
+          if (Buffer.isBuffer(chunkOrError)) {
+            chunk$.next(chunkOrError);
+          } else {
+            chunk$.error(chunkOrError);
+          }
+        },
+        error(error) {
+          chunk$.error(error);
+        },
+        complete() {
+          if (!socket.destroyed) {
+            socket.destroy();
+          }
+
+          chunk$.complete();
+        },
+      });
+  });
+
+  const readyPromise = Rx.race(
+    Rx.fromEvent<void>(server, 'listening').pipe(take(1)),
+    Rx.fromEvent<Error>(server, 'error').pipe(
+      map(error => {
+        throw error;
+      })
+    )
+  ).toPromise();
+
+  server.listen(0);
+  cleanup$.subscribe(() => {
+    server.close();
+  });
+
+  await readyPromise;
+
+  const addressInfo = server.address();
+  if (typeof addressInfo === 'string') {
+    throw new Error('server must listen to a random port, not a unix socket');
+  }
+
+  const input = Net.createConnection(addressInfo.port, addressInfo.address);
+  await Rx.fromEvent<void>(input, 'connect')
+    .pipe(take(1))
+    .toPromise();
+
+  return {
+    input,
+    chunk$,
+    cleanup() {
+      cleanup$.next();
+      cleanup$.complete();
+    },
+  };
+}

test/functional/services/remote/remote.ts

@@ -27,7 +27,12 @@ export async function RemoteProvider({ getService }: FtrProviderContext) {
   const config = getService('config');
   const browserType: Browsers = config.get('browser.type');
 
-  const { driver, By, until } = await initWebDriver(log, browserType);
+  const { driver, By, until, consoleLog$ } = await initWebDriver(
+    log,
+    browserType,
+    lifecycle,
+    config.get('browser.logPollingMs')
+  );
   const isW3CEnabled = (driver as any).executor_.w3c;
 
   const caps = await driver.getCapabilities();
@@ -74,5 +79,5 @@ export async function RemoteProvider({ getService }: FtrProviderContext) {
 
   lifecycle.on('cleanup', async () => await driver.quit());
 
-  return { driver, By, until, browserType };
+  return { driver, By, until, browserType, consoleLog$ };
 }

test/functional/services/remote/webdriver.ts

@@ -17,6 +17,8 @@
  * under the License.
  */
 
+import { mergeMap, map, takeUntil } from 'rxjs/operators';
+import { Lifecycle } from '@kbn/test/src/functional_test_runner/lib/lifecycle';
 import { ToolingLog } from '@kbn/dev-utils';
 import { delay } from 'bluebird';
 import chromeDriver from 'chromedriver';
@@ -30,6 +32,8 @@ import { Executor } from 'selenium-webdriver/lib/http';
 // @ts-ignore internal modules are not typed
 import { getLogger } from 'selenium-webdriver/lib/logging';
 
+import { pollForLogEntry$ } from './poll_for_log_entry';
+import { createStdoutSocket } from './create_stdout_stream';
 import { preventParallelCalls } from './prevent_parallel_calls';
 
 import { Browsers } from './browsers';
@@ -54,13 +58,18 @@ Executor.prototype.execute = preventParallelCalls(
 );
 
 let attemptCounter = 0;
-async function attemptToCreateCommand(log: ToolingLog, browserType: Browsers) {
+async function attemptToCreateCommand(
+  log: ToolingLog,
+  browserType: Browsers,
+  lifecycle: Lifecycle,
+  logPollingMs: number
+) {
   const attemptId = ++attemptCounter;
   log.debug('[webdriver] Creating session');
 
   const buildDriverInstance = async () => {
     switch (browserType) {
-      case 'chrome':
+      case 'chrome': {
         const chromeCapabilities = Capabilities.chrome();
         const chromeOptions = [
           'disable-translate',
@@ -80,28 +89,77 @@ async function attemptToCreateCommand(log: ToolingLog, browserType: Browsers) {
           args: chromeOptions,
         });
         chromeCapabilities.set('goog:loggingPrefs', { browser: 'ALL' });
-        return new Builder()
+
+        const session = await new Builder()
           .forBrowser(browserType)
           .withCapabilities(chromeCapabilities)
           .setChromeService(new chrome.ServiceBuilder(chromeDriver.path).enableVerboseLogging())
           .build();
-      case 'firefox':
+
+        return {
+          session,
+          consoleLog$: pollForLogEntry$(session, logging.Type.BROWSER, logPollingMs).pipe(
+            takeUntil(lifecycle.cleanup$),
+            map(({ message, level: { name: level } }) => ({
+              message: message.replace(/\\n/g, '\n'),
+              level,
+            }))
+          ),
+        };
+      }
+
+      case 'firefox': {
         const firefoxOptions = new firefox.Options();
+        // Firefox 65+ supports logging console output to stdout
+        firefoxOptions.set('moz:firefoxOptions', {
+          prefs: { 'devtools.console.stdout.content': true },
+        });
         if (headlessBrowser === '1') {
           // See: https://developer.mozilla.org/en-US/docs/Mozilla/Firefox/Headless_mode
           firefoxOptions.headless();
         }
-        return new Builder()
+        const { input, chunk$, cleanup } = await createStdoutSocket();
+        lifecycle.on('cleanup', cleanup);
+
+        const session = await new Builder()
           .forBrowser(browserType)
           .setFirefoxOptions(firefoxOptions)
-          .setFirefoxService(new firefox.ServiceBuilder(geckoDriver.path).enableVerboseLogging())
+          .setFirefoxService(
+            new firefox.ServiceBuilder(geckoDriver.path).setStdio(['ignore', input, 'ignore'])
+          )
           .build();
+
+        const CONSOLE_LINE_RE = /^console\.([a-z]+): ([\s\S]+)/;
+
+        return {
+          session,
+          consoleLog$: chunk$.pipe(
+            map(chunk => chunk.toString('utf8')),
+            mergeMap(msg => {
+              const match = msg.match(CONSOLE_LINE_RE);
+              if (!match) {
+                log.debug('Firefox stdout: ' + msg);
+                return [];
+              }
+
+              const [, level, message] = match;
+              return [
+                {
+                  level,
+                  message: message.trim(),
+                },
+              ];
+            })
+          ),
+        };
+      }
+
       default:
         throw new Error(`${browserType} is not supported yet`);
     }
   };
 
-  const session = await buildDriverInstance();
+  const { session, consoleLog$ } = await buildDriverInstance();
 
   if (throttleOption === '1' && browserType === 'chrome') {
     // Only chrome supports this option.
@@ -119,10 +177,15 @@ async function attemptToCreateCommand(log: ToolingLog, browserType: Browsers) {
     return;
   } // abort
 
-  return { driver: session, By, until };
+  return { driver: session, By, until, consoleLog$ };
 }
 
-export async function initWebDriver(log: ToolingLog, browserType: Browsers) {
+export async function initWebDriver(
+  log: ToolingLog,
+  browserType: Browsers,
+  lifecycle: Lifecycle,
+  logPollingMs: number
+) {
   const logger = getLogger('webdriver.http.Executor');
   logger.setLevel(logging.Level.FINEST);
   logger.addHandler((entry: { message: string }) => {
@@ -144,7 +207,7 @@ export async function initWebDriver(log: ToolingLog, browserType: Browsers) {
       while (true) {
         const command = await Promise.race([
           delay(30 * SECOND),
-          attemptToCreateCommand(log, browserType),
+          attemptToCreateCommand(log, browserType, lifecycle, logPollingMs),
         ]);
 
         if (!command) {