From 551ac4b659a9afc1a6745e1a9349c26b35f33b25 Mon Sep 17 00:00:00 2001 From: Christophe Monniez Date: Thu, 19 Jul 2018 12:04:21 +0200 Subject: [PATCH] [REF] tests: replace phantomjs by Chrome headless As the phantomjs project was suspended[1], there was a need to change the js test engine. Moreover, the engine was rather old and leading to non deterministic crashes. Chrome headless was choosen for simplicity and the long term vision of the devtools protocol [2]. The 'phantom_js' method still exists but will be deprecated in favor of 'browser_js' with the same parameters. In order to communicate with the browser, the python websocket-client package is needed. [1] https://github.com/ariya/phantomjs/issues/15344 [2] https://chromedevtools.github.io/devtools-protocol/ --- odoo/tests/common.py | 486 +++++++++++++++++++++++++++----------- odoo/tests/phantomtest.js | 145 ------------ 2 files changed, 346 insertions(+), 285 deletions(-) delete mode 100644 odoo/tests/phantomtest.js diff --git a/odoo/tests/common.py b/odoo/tests/common.py index a5c2c9a4a00fa..f843dd75fd91d 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -4,6 +4,7 @@ helpers and classes to write tests. """ +import base64 import collections import errno import glob @@ -14,16 +15,22 @@ import operator import os import re +import requests import select +import shutil +import socket import subprocess +import sys +import tempfile import threading import time import unittest +import websocket +import werkzeug.urls from contextlib import contextmanager from datetime import datetime, timedelta, date from pprint import pformat -import requests from decorator import decorator from lxml import etree, html @@ -389,10 +396,282 @@ def tearDown(self): super(SavepointCase, self).tearDown() +class ChromeBrowser(): + + def __init__(self): + self.devtools_port = PORT + 2 + self.ws_url = '' # WebSocketUrl + self.ws = None # websocket + self.request_id = 0 + self.user_data_dir = '' + self.chrome_process = None + self.screencast_frames = [] + self._chrome_start(['google-chrome'], self.user_data_dir) + _logger.info('Websocket url found: %s' % self.ws_url) + self._open_websocket() + _logger.info('Enable chrome headless console log notification') + self._websocket_send('Runtime.enable') + _logger.info('Chrome headless enable page notifications') + self._websocket_send('Page.enable') + + def stop(self): + if self.chrome_process is not None: + _logger.info("Closing chrome headless with pid %s" % self.chrome_process.pid) + self._websocket_send('Browser.close') + if self.chrome_process.poll() is None: + _logger.info("Terminating chrome headless with pid %s" % self.chrome_process.pid) + self.chrome_process.terminate() + self.chrome_process.wait() + if self.user_data_dir and os.path.isdir(self.user_data_dir) and self.user_data_dir != '/': + _logger.info('Removing chrome user profile "%s"' % self.user_data_dir) + shutil.rmtree(self.user_data_dir) + + def _chrome_start(self, cmd, user_data_dir): + if self.chrome_process is not None: + return + switches = { + '--headless': '', + '--enable-logging': 'stderr', + '--no-default-browser-check': '', + '--no-first-run': '', + '--disable-extensions': '', + '--user-data-dir': user_data_dir, + '--disable-translate': '', + '--window-size': '1366x768', + '--remote-debugging-port': str(self.devtools_port) + } + cmd += ['%s=%s' % (k, v) if v else k for k, v in switches.items()] + url = 'about:blank' + cmd.append(url) + _logger.info('chrome_run executing %s', ' '.join(cmd)) + try: + self.chrome_process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) + except OSError: + raise unittest.SkipTest("%s not found" % cmd[0]) + _logger.info('Chrome pid: %s' % self.chrome_process.pid) + version = self._json_command('version') + _logger.info('Browser version: %s' % version['Browser']) + infos = self._json_command('')[0] # Infos about the first tab + self.ws_url = infos['webSocketDebuggerUrl'] + self.user_data_dir = tempfile.mkdtemp(suffix='_chrome_odoo') + _logger.info('Chrome headless temporary user profile dir: %s' % self.user_data_dir) + + def _json_command(self, command, timeout=3): + """ + Inspect dev tools with get + Available commands: + '' : return list of tabs with their id + list (or json/): list tabs + new : open a new tab + activate/ + an id: activate a tab + close/ + and id: close a tab + version : get chrome and dev tools version + protocol : get the full protocol + """ + _logger.info("Issuing json command %s" % command) + command = os.path.join('json', command).strip('/') + while timeout > 0: + try: + url = werkzeug.urls.url_join('http://127.0.0.1:%s/' % self.devtools_port, command) + _logger.info('Url : %s' % url) + r = requests.get(url, timeout=3) + if r.ok: + return r.json() + return {'status_code': r.status_code} + except requests.ConnectionError: + time.sleep(0.1) + timeout -= 0.1 + except requests.exceptions.ReadTimeout: + break + _logger.error('Could not connect to chrome debugger') + raise unittest.SkipTest("Cannot connect to chrome headless") + + def _open_websocket(self): + self.ws = websocket.create_connection(self.ws_url) + if self.ws.getstatus() != 101: + raise unittest.SkipTest("Cannot connect to chrome dev tools") + self.ws.settimeout(0.01) + + def _websocket_send(self, method, params=None): + """ + send chrome devtools protocol commands through websocket + """ + sent_id = self.request_id + payload = { + 'method': method, + 'id': sent_id, + } + if params: + payload.update({'params': params}) + self.ws.send(json.dumps(payload)) + self.request_id += 1 + return sent_id + + def _websocket_wait_id(self, awaited_id, timeout=10): + """ + blocking wait for a certain id in a response + warning other messages are discarded + """ + start_time = time.time() + while time.time() - start_time < timeout: + try: + res = json.loads(self.ws.recv()) + except websocket.WebSocketTimeoutException: + res = None + if res and res.get('id') == awaited_id: + return res + _logger.info('timeout exceeded while waiting for id : %d' % awaited_id) + return {} + + def _websocket_wait_event(self, method, params=None, timeout=10): + """ + blocking wait for a particular event method and eventually a dict of params + """ + start_time = time.time() + while time.time() - start_time < timeout: + try: + res = json.loads(self.ws.recv()) + except websocket.WebSocketTimeoutException: + res = None + if res and res.get('method', '') == method: + if params: + if set(params).issubset(set(res.get('params', {}))): + return res + else: + return res + elif res: + _logger.debug('chrome devtools protocol event: %s' % res) + _logger.info('timeout exceeded while waiting for : %s' % method) + + def _get_shotname(self, prefix, ext): + """ return a unique filename for screenshot or screencast""" + timestamp = datetime.now().strftime('%Y%m%d_%H%M%S_%f') + base_file = os.path.splitext(odoo.tools.config['logfile'])[0] + name = '%s_%s_%s.%s' % (base_file, prefix, timestamp, ext) + return name + + def take_screenshot(self, prefix='failed'): + if not odoo.tools.config['logfile']: + _logger.info('Screenshot disabled !') + return None + ss_id = self._websocket_send('Page.captureScreenshot') + _logger.info('Asked for screenshot (id: %s)' % ss_id) + res = self._websocket_wait_id(ss_id) + base_png = res.get('result', {}).get('data') + decoded = base64.decodebytes(bytes(base_png.encode('utf-8'))) + outfile = self._get_shotname(prefix, 'png') + with open(outfile, 'wb') as f: + f.write(decoded) + _logger.info('Screenshot in: %s' % outfile) + + def _save_screencast(self, prefix='failed'): + # could be encododed with something like that + # ffmpeg -framerate 3 -i frame_%05d.png output.mp4 + if not odoo.tools.config['logfile']: + _logger.info('Screencast disabled !') + return None + sdir = tempfile.mkdtemp(suffix='_chrome_odoo_screencast') + nb = 0 + for frame in self.screencast_frames: + outfile = os.path.join(sdir, 'frame_%05d.png' % nb) + with open(outfile, 'wb') as f: + f.write(base64.decodebytes(bytes(frame.get('data').encode('utf-8')))) + nb += 1 + framerate = int(nb / (self.screencast_frames[nb-1].get('metadata').get('timestamp') - self.screencast_frames[0].get('metadata').get('timestamp'))) + outfile = self._get_shotname(prefix, 'mp4') + r = subprocess.run(['ffmpeg', '-framerate', str(framerate), '-i', '%s/frame_%%05d.png' % sdir, outfile]) + shutil.rmtree(sdir) + if r.returncode == 0: + _logger.info('Screencast in: %s' % outfile) + + def start_screencast(self): + self._websocket_send('Page.startScreencast', {'params': {'everyNthFrame': 5, 'maxWidth': 683, 'maxHeight': 384}}) + + def set_cookie(self, name, value, path, domain): + params = {'name': name, 'value': value, 'path': path, 'domain': domain} + self._websocket_send('Network.setCookie', params=params) + + def _wait_ready(self, ready_code, timeout=10): + _logger.info('Evaluate ready code "%s"' % ready_code) + awaited_result = {'result': {'type': 'boolean', 'value': True}} + ready_id = self._websocket_send('Runtime.evaluate', params={'expression': ready_code}) + last_bad_res = '' + start_time = time.time() + while time.time() - start_time < timeout: + try: + res = json.loads(self.ws.recv()) + except websocket.WebSocketTimeoutException: + res = None + if res and res.get('id') == ready_id: + if res.get('result') == awaited_result: + return True + else: + last_bad_res = res + ready_id = self._websocket_send('Runtime.evaluate', params={'expression': ready_code}) + self.take_screenshot(prefix='failed_ready') + _logger.info('Ready code last try result: %s' % last_bad_res or res) + return False + + def _wait_code_ok(self, code, timeout): + _logger.info('Evaluate test code "%s"' % code) + code_id = self._websocket_send('Runtime.evaluate', params={'expression': code}) + start_time = time.time() + while time.time() - start_time < timeout: + try: + res = json.loads(self.ws.recv()) + except websocket.WebSocketTimeoutException: + res = None + if res and res.get('id', -1) == code_id: + _logger.info('Code start result: %s' % res) + if res.get('result', {}).get('result').get('subtype', '') == 'error': + _logger.error("Running code returned an error") + self.browser_cleanup() + return False + elif res and res.get('method') == 'Runtime.consoleAPICalled' and res.get('params', {}).get('type') == 'log': + logs = res.get('params', {}).get('args') + for log in logs: + _logger.info('console logs: %s' % log.get('value', '')) + if log.get('type', '') == 'string' and log.get('value', '').lower() == 'ok': + return True + elif log.get('type', '') == 'string' and log.get('value', '').lower().startswith('error'): + self.take_screenshot() + self._save_screencast() + self.browser_cleanup() + return False + elif res and res.get('method') == 'Page.screencastFrame': + self.screencast_frames.append(res.get('params')) + elif res: + _logger.debug('chrome devtools protocol event: %s' % res) + _logger.error('Script timeout exceeded : %s' % (time.time() - start_time)) + self.take_screenshot() + return False + + def navigate_to(self, url, wait_stop=False): + _logger.info('Navigating to: "%s"' % url) + nav_id = self._websocket_send('Page.navigate', params={'url': url}) + nav_result = self._websocket_wait_id(nav_id) + _logger.info("Navigation result: %s" % nav_result) + frame_id = nav_result.get('result', {}).get('frameId', '') + if wait_stop and frame_id: + _logger.info('Waiting for frame "%s" to stop loading' % frame_id) + self._websocket_wait_event('Page.frameStoppedLoading', params={'frameId': frame_id}) + + def browser_cleanup(self): + self._websocket_send('Page.stopScreencast') + self.screencast_frames = [] + self._websocket_send('Page.stopLoading') + _logger.info('Deleting cookies and clearing local storage') + dc_id = self._websocket_send('Network.clearBrowserCookies') + self._websocket_wait_id(dc_id) + cl_id = self._websocket_send('Runtime.evaluate', params={'expression': 'localStorage.clear()'}) + self._websocket_wait_id(cl_id) + self.navigate_to('about:blank', wait_stop=True) + class HttpCase(TransactionCase): - """ Transactional HTTP TestCase with url_open and phantomjs helpers. + """ Transactional HTTP TestCase with url_open and Chrome headless helpers. """ registry_test_mode = True + chrome_browser = None def __init__(self, methodName='runTest'): super(HttpCase, self).__init__(methodName) @@ -404,8 +683,21 @@ def __init__(self, methodName='runTest'): cls = type(self) self._logger = logging.getLogger('%s.%s' % (cls.__module__, cls.__name__)) + @classmethod + def start_chrome(cls): + if cls.chrome_browser is None: + cls.chrome_browser = ChromeBrowser() + + @classmethod + def tearDownClass(cls): + if cls.chrome_browser: + cls.chrome_browser.stop() + cls.chrome_browser = None + super(HttpCase, cls).tearDownClass() + def setUp(self): super(HttpCase, self).setUp() + if self.registry_test_mode: self.registry.enter_test_mode(self.cr) self.addCleanup(self.registry.leave_test_mode) @@ -425,6 +717,27 @@ def url_open(self, url, data=None, timeout=10): return self.opener.post(url, data=data, timeout=timeout) return self.opener.get(url, timeout=timeout) + def _wait_remaining_requests(self): + t0 = int(time.time()) + for thread in threading.enumerate(): + if thread.name.startswith('odoo.service.http.request.'): + join_retry_count = 10 + while thread.isAlive(): + # Need a busyloop here as thread.join() masks signals + # and would prevent the forced shutdown. + thread.join(0.05) + join_retry_count -= 1 + if join_retry_count < 0: + _logger.warning("Stop waiting for thread %s handling request for url %s", + thread.name, thread.url) + break + time.sleep(0.5) + t1 = int(time.time()) + if t0 != t1: + _logger.info('remaining requests') + odoo.tools.misc.dumpstacks() + t0 = t1 + def authenticate(self, user, password): # stay non-authenticated if user is None: @@ -448,132 +761,11 @@ def authenticate(self, user, password): session._fix_lang(session.context) odoo.http.root.session_store.save(session) + if self.chrome_browser: + _logger.info('Setting session cookie in chrome headless') + self.chrome_browser.set_cookie('session_id', self.session_id, '/', '127.0.0.1') - def phantom_poll(self, phantom, timeout): - """ Phantomjs Test protocol. - - Use console.log in phantomjs to output test results: - - - for a success: console.log("ok") - - for an error: console.log("error") - - Other lines are relayed to the test log. - - """ - logger = self._logger.getChild('phantomjs') - t0 = datetime.now() - td = timedelta(seconds=timeout) - buf = bytearray() - pid = phantom.stdout.fileno() - while True: - # timeout - self.assertLess(datetime.now() - t0, td, - "PhantomJS tests should take less than %s seconds" % timeout) - - # read a byte - try: - ready, _, _ = select.select([pid], [], [], 0.5) - except select.error as e: - # In Python 2, select.error has no relation to IOError or - # OSError, and no errno/strerror/filename, only a pair of - # unnamed arguments (matching errno and strerror) - err, _ = e.args - if err == errno.EINTR: - continue - raise - - if not ready: - continue - - s = os.read(pid, 4096) - if not s: - self.fail("Ran out of data to read") - buf.extend(s) - - # process lines - while b'\n' in buf and (not buf.startswith(b'') or b'' in buf): - - if buf.startswith(b''): - line, buf = buf[12:].split(b'\n', 1) - else: - line, buf = buf.split(b'\n', 1) - line = line.decode('utf-8') - - lline = line.lower() - if lline.startswith(("error", "server application error")): - try: - # when errors occur the execution stack may be sent as a JSON - prefix = lline.index('error') + 6 - self.fail(pformat(json.loads(line[prefix:]))) - except ValueError: - self.fail(lline) - elif lline.startswith("warning"): - logger.warn(line) - else: - logger.info(line) - - if line == "ok": - return True - - def phantom_run(self, cmd, timeout): - _logger.info('phantom_run executing %s', ' '.join(cmd)) - - ls_glob = os.path.expanduser('~/.qws/share/data/Ofi Labs/PhantomJS/http_%s_%s.*' % (HOST, PORT)) - ls_glob2 = os.path.expanduser('~/.local/share/Ofi Labs/PhantomJS/http_%s_%s.*' % (HOST, PORT)) - for i in (glob.glob(ls_glob) + glob.glob(ls_glob2)): - _logger.info('phantomjs unlink localstorage %s', i) - os.unlink(i) - try: - phantom = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=None) - except OSError: - raise unittest.SkipTest("PhantomJS not found") - try: - result = self.phantom_poll(phantom, timeout) - self.assertTrue( - result, - "PhantomJS test completed without reporting success; " - "the log may contain errors or hints.") - finally: - # kill phantomjs if phantom.exit() wasn't called in the test - if phantom.poll() is None: - _logger.info("Terminating phantomjs") - phantom.terminate() - phantom.wait() - else: - # if we had to terminate phantomjs its return code is - # always -15 so we don't care - # check PhantomJS health - from signal import SIGSEGV - _logger.info("Phantom JS return code: %d" % phantom.returncode) - if phantom.returncode == -SIGSEGV: - _logger.error("Phantom JS has crashed (segmentation fault) during testing; log may not be relevant") - elif phantom.returncode < 0: - _logger.error("Phantom JS probably crashed (Phantom JS return code: %d)" % phantom.returncode) - - self._wait_remaining_requests() - - def _wait_remaining_requests(self): - t0 = int(time.time()) - for thread in threading.enumerate(): - if thread.name.startswith('odoo.service.http.request.'): - join_retry_count = 10 - while thread.isAlive(): - # Need a busyloop here as thread.join() masks signals - # and would prevent the forced shutdown. - thread.join(0.05) - join_retry_count -= 1 - if join_retry_count < 0: - _logger.warning("Stop waiting for thread %s handling request for url %s", - thread.name, thread.url) - break - time.sleep(0.5) - t1 = int(time.time()) - if t0 != t1: - _logger.info('remaining requests') - odoo.tools.misc.dumpstacks() - t0 = t1 - - def phantom_js(self, url_path, code, ready="window", login=None, timeout=60, **kw): + def browser_js(self, url_path, code, ready='', login=None, timeout=60, **kw): """ Test js code running in the browser - optionnally log as 'login' - load page given by url_path @@ -588,23 +780,37 @@ def phantom_js(self, url_path, code, ready="window", login=None, timeout=60, **k If neither are done before timeout test fails. """ - options = { - 'port': PORT, - 'db': get_db_name(), - 'url_path': url_path, - 'code': code, - 'ready': ready, - 'timeout' : timeout, - 'session_id': self.session_id, - } - options.update(kw) + + # Start chrome only if needed (instead of using a setupClass) + self.start_chrome() self.authenticate(login, login) + url = "http://%s:%s%s" % (HOST, PORT, url_path or '/') + _logger.info('Open "%s" in chrome headless' % url) + + _logger.info('Starting screen cast') + self.chrome_browser.start_screencast() + self.chrome_browser.navigate_to(url) + + # Needed because tests like test01.js (qunit tests) are passing a ready + # code = "" + ready = ready or "document.readyState === 'complete'" + self.assertTrue( + self.chrome_browser._wait_ready(ready), + 'The ready "%s" code was always falsy' % ready + ) + + self.assertTrue( + self.chrome_browser._wait_code_ok(code, timeout), + 'The test code "%s" failed' % code + ) - phantomtest = os.path.join(os.path.dirname(__file__), 'phantomtest.js') - cmd = ['phantomjs', phantomtest, json.dumps(options)] - self.phantom_run(cmd, timeout) + # better at the end of the method, in case we call the method multiple + # times in the same test + self.chrome_browser.browser_cleanup() + self._wait_remaining_requests() + phantom_js = browser_js def users(*logins): """ Decorate a method to execute it once for each given user. """ diff --git a/odoo/tests/phantomtest.js b/odoo/tests/phantomtest.js deleted file mode 100644 index b77cc3ffe9d59..0000000000000 --- a/odoo/tests/phantomtest.js +++ /dev/null @@ -1,145 +0,0 @@ -// Phantomjs odoo helper -// jshint evil: true, loopfunc: true - -var system = require('system'); -var HOST = '127.0.0.1'; - -function waitFor (condition, callback, timeout, timeoutMessageCallback) { - timeout = timeout || 10000; - var start = new Date(); - - (function waitLoop() { - if(new Date() - start > timeout) { - console.log('error', timeoutMessageCallback ? timeoutMessageCallback() : "Timeout after "+timeout+" ms"); - phantom.exit(1); - } else if (condition()) { - callback(); - } else { - setTimeout(waitLoop, 250); - } - }()); -} - -function PhantomTest() { - var self = this; - this.options = JSON.parse(system.args[system.args.length-1]); - this.inject = this.options.inject || []; - this.timeout = this.options.timeout ? Math.round(parseFloat(this.options.timeout)*1000 - 5000) : 10000; - this.origin = 'http://' + HOST; - this.origin += this.options.port ? ':' + this.options.port : ''; - - // ---------------------------------------------------- - // configure phantom and page - // ---------------------------------------------------- - phantom.addCookie({ - 'domain': HOST, - 'name': 'session_id', - 'value': this.options.session_id, - }); - this.page = require('webpage').create(); - this.page.viewportSize = { width: 1366, height: 768 }; - this.page.onError = function(message, trace) { - var msg = [message]; - if (trace && trace.length) { - msg.push.apply(msg, trace.map(function (frame) { - var result = [' at ', frame.file, ':', frame.line]; - if (frame.function) { - result.push(' (in ', frame.function, ')'); - } - return result.join(''); - })); - msg.push('(leaf frame on top)'); - } - console.log('error', JSON.stringify(msg.join('\n'))); - phantom.exit(1); - }; - this.page.onAlert = function(message) { - console.log('error', message); - phantom.exit(1); - }; - this.page.onConsoleMessage = function(message) { - console.log(''+message+''); - }; - this.page.onLoadFinished = function(status) { - console.log('PhantomJS: onLoadFinished. Status=', status); - if (status === "success") { - for (var k in self.inject) { - var found = false; - var v = self.inject[k]; - var need = v; - var src = v; - if (v[0]) { - need = v[0]; - src = v[1]; - found = self.page.evaluate(function(code) { - try { - return !!eval(code); - } catch (e) { - return false; - } - }, need); - } - if(!found) { - console.log('Injecting', src, 'needed for', need); - if(!self.page.injectJs(src)) { - console.log('error', "Cannot inject " + src); - phantom.exit(1); - } - } - } - } - }; - setTimeout(function () { - self.page.evaluate(function () { - var message = ("Timeout\nhref: " + window.location.href + - "\nreferrer: " + document.referrer + - "\n\n" + (document.body && document.body.innerHTML)).replace(/[^a-z0-9\s~!@#$%^&*()_|+\-=?;:'",.<>\{\}\[\]\\\/]/gi, "*"); - console.log('error ' + message + ''); - }); - phantom.exit(1); - }, self.timeout); - - // ---------------------------------------------------- - // run test - // ---------------------------------------------------- - this.run = function(url_path, code, ready) { - var url = self.origin + url_path; - code = code || "true"; - ready = ready || "true"; - self.page.open(url, function(status) { - if (status !== 'success') { - console.log('error', "failed to load " + url); - phantom.exit(1); - } else { - console.log('loaded', url, status); - // clear localstorage leftovers - self.page.evaluate(function () { localStorage.clear() }); - // process ready - waitFor(function() { - console.log("PhantomTest.run: wait for condition:", ready); - return self.page.evaluate(function (ready) { - var r = false; - try { - console.log("page.evaluate eval expr:", ready); - r = !!eval(ready); - } catch(ex) { - } - console.log("page.evaluate eval result:", r); - return r; - }, ready); - // run test - }, function() { - console.log("PhantomTest.run: condition statified, executing: " + code); - self.page.evaluate(function (code) { return eval(code); }, code); - console.log("PhantomTest.run: execution launched, waiting for console.log('ok')..."); - }); - } - }); - }; -} - -// js mode or jsfile mode -if(system.args.length === 2) { - pt = new PhantomTest(); - pt.run(pt.options.url_path, pt.options.code, pt.options.ready); -}