[7.x] [ftr/browser] poll for logs and stream them (#40098) (#40154)

src/functional_test_runner/lib/config/schema.ts

@@ -136,6 +136,8 @@ export const schema = Joi.object()
         type: Joi.string()
           .valid('chrome', 'firefox')
           .default('chrome'),
+
+        logPollingMs: Joi.number().default(100),
       })
       .default(),
 

src/functional_test_runner/lib/lifecycle.ts

@@ -17,6 +17,8 @@
  * under the License.
  */
 
+import * as Rx from 'rxjs';
+
 type Listener = (...args: any[]) => Promise<void> | void;
 export type Lifecycle = ReturnType<typeof createLifecycle>;
 
@@ -34,7 +36,11 @@ export function createLifecycle() {
     phaseEnd: [] as Listener[],
   };
 
+  const cleanup$ = new Rx.ReplaySubject(1);
+
   return {
+    cleanup$: cleanup$.asObservable(),
+
     on(name: keyof typeof listeners, fn: Listener) {
       if (!listeners[name]) {
         throw new TypeError(`invalid lifecycle event "${name}"`);
@@ -49,6 +55,15 @@ export function createLifecycle() {
         throw new TypeError(`invalid lifecycle event "${name}"`);
       }
 
+      if (name === 'cleanup') {
+        if (cleanup$.closed) {
+          return;
+        }
+
+        cleanup$.next();
+        cleanup$.complete();
+      }
+
       try {
         if (name !== 'phaseStart' && name !== 'phaseEnd') {
           await this.trigger('phaseStart', name);

test/functional/services/browser.ts

@@ -19,21 +19,40 @@
 
 import { cloneDeep } from 'lodash';
 import { IKey, logging } from 'selenium-webdriver';
+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, Key, LegacyActionSequence, browserType } = await getService(
     '__webdriver__'
   ).init();
 
-  class BrowserService {
+  const isW3CEnabled = (driver as any).executor_.w3c === true;
+
+  if (!isW3CEnabled) {
+    // 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
      */
@@ -51,7 +70,7 @@ export async function BrowserProvider({ getService }: FtrProviderContext) {
     /**
      * Is WebDriver instance W3C compatible
      */
-    isW3CEnabled = (driver as any).executor_.w3c === true;
+    isW3CEnabled = isW3CEnabled;
 
     /**
      * Returns instance of Actions API based on driver w3c flag
@@ -338,29 +357,6 @@ export async function BrowserProvider({ getService }: FtrProviderContext) {
       return await driver.getPageSource();
     }
 
-    /**
-     * Gets all logs from the remote environment of the given type. The logs in the remote
-     * environment are cleared once they have been retrieved.
-     * https://seleniumhq.github.io/selenium/docs/api/javascript/module/selenium-webdriver/lib/webdriver_exports_Logs.html#get
-     *
-     * @param {!logging.Type} type The desired log type.
-     * @return {Promise<LogEntry[]>}
-     */
-    public async getLogsFor(type: typeof logging.Type | string): Promise<logging.Entry[]>;
-    public async getLogsFor(...args: any[]): Promise<logging.Entry[]> {
-      // 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
-      if (this.isW3CEnabled) {
-        return [];
-      } else {
-        return await (driver as any)
-          .manage()
-          .logs()
-          .get(...args);
-      }
-    }
-
     /**
      * Gets a screenshot of the focused window and returns it as a base-64 encoded PNG
      * https://seleniumhq.github.io/selenium/docs/api/javascript/module/selenium-webdriver/lib/webdriver_exports_WebDriver.html#takeScreenshot
@@ -494,7 +490,5 @@ export async function BrowserProvider({ getService }: FtrProviderContext) {
       await driver.executeScript('document.body.scrollLeft = ' + scrollSize);
       return this.getScrollLeft();
     }
-  }
-
-  return new BrowserService();
+  }();
 }

test/functional/services/failure_debugging.js

@@ -48,13 +48,7 @@ export async function FailureDebuggingProvider({ getService }) {
     await writeFileAsync(htmlOutputFileName, pageSource);
   }
 
-  async function logBrowserConsole() {
-    const browserLogs = await browser.getLogsFor('browser');
-    const browserOutput = browserLogs.reduce((acc, log) => acc += `${log.message.replace(/\\n/g, '\n')}\n`, '');
-    log.info(`Browser output is: ${browserOutput}`);
-  }
-
-  async function onFailure(error, test) {
+  async function onFailure(_, test) {
     // Replace characters in test names which can't be used in filenames, like *
     const name = test.fullTitle().replace(/([^ a-zA-Z0-9-]+)/g, '_');
 
@@ -62,15 +56,10 @@ export async function FailureDebuggingProvider({ getService }) {
       screenshots.takeForFailure(name),
       logCurrentUrl(),
       savePageHtml(name),
-      logBrowserConsole(),
     ]);
   }
 
   lifecycle
     .on('testFailure', onFailure)
     .on('testHookFailure', onFailure);
-
-  return {
-    logBrowserConsole
-  };
 }

test/functional/services/remote/poll_for_log_entry.ts

@@ -0,0 +1,66 @@
+/*
+ * 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 { WebDriver, logging } from 'selenium-webdriver';
+import * as Rx from 'rxjs';
+import { mergeMap, catchError, repeatWhen, mergeMapTo, delay } from 'rxjs/operators';
+
+/**
+ * Create an observable that emits log entries representing the calls to log messages
+ * available for a specific logger.
+ */
+export function pollForLogEntry$(driver: WebDriver, type: string, ms: number) {
+  const logCtrl = driver.manage().logs();
+
+  // setup log polling
+  return Rx.defer(async () => await logCtrl.get(type)).pipe(
+    // filter and flatten list of entries
+    mergeMap(entries =>
+      entries.filter(entry => {
+        // ignore react devtools
+        if (entry.message.includes('Download the React DevTools')) {
+          return false;
+        }
+
+        // down-level inline script errors
+        if (entry.message.includes('Refused to execute inline script')) {
+          entry.level = logging.getLevel('INFO');
+        }
+
+        return true;
+      })
+    ),
+
+    // repeat when parent completes, delayed by `ms` milliseconds
+    repeatWhen($ => $.pipe(delay(ms))),
+
+    catchError((error, resubscribe) => {
+      return Rx.concat(
+        // log error as a log entry
+        [new logging.Entry('SEVERE', `ERROR FETCHING BROWSR LOGS: ${error.message}`)],
+
+        // pause 10 seconds then resubscribe
+        Rx.of(1).pipe(
+          delay(10 * 1000),
+          mergeMapTo(resubscribe)
+        )
+      );
+    })
+  );
+}

test/functional/services/remote/webdriver.ts

@@ -41,7 +41,7 @@ import { Browsers } from './browsers';
 const throttleOption = process.env.TEST_THROTTLE_NETWORK;
 const SECOND = 1000;
 const MINUTE = 60 * SECOND;
-const NO_QUEUE_COMMANDS = ['getStatus', 'newSession', 'quit'];
+const NO_QUEUE_COMMANDS = ['getLog', 'getStatus', 'newSession', 'quit'];
 
 /**
  * Best we can tell WebDriver locks up sometimes when we send too many
@@ -119,6 +119,11 @@ export async function initWebDriver(log: ToolingLog, browserType: Browsers) {
   const logger = getLogger('webdriver.http.Executor');
   logger.setLevel(logging.Level.FINEST);
   logger.addHandler((entry: { message: string }) => {
+    if (entry.message.match(/\/session\/\w+\/log\b/)) {
+      // ignore polling requests for logs
+      return;
+    }
+
     log.verbose(entry.message);
   });