From 35eaa523bda9974089b49436a43c63d2b4339ff7 Mon Sep 17 00:00:00 2001 From: Xavier Morel Date: Tue, 14 Aug 2018 15:32:57 +0200 Subject: [PATCH 01/15] [IMP] tests logging * Make phantomjs logging clearer by logging within the test case's module, not odoo.tests.common. This way, a tour in e.g. point of sale is clearly logged as that, rather than be logged as odoo.tests.common.phantomjs and require hunting which module/test we happen to be in. * Clarify tagging causes for exclusion of selection of tests. --- odoo/tests/common.py | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index b2e0b449b43..3579e2f3cd4 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -338,6 +338,8 @@ class HttpCase(TransactionCase): self.xmlrpc_common = xmlrpclib.ServerProxy(url_8 + 'common') self.xmlrpc_db = xmlrpclib.ServerProxy(url_8 + 'db') self.xmlrpc_object = xmlrpclib.ServerProxy(url_8 + 'object') + cls = type(self) + self._logger = logging.getLogger('%s.%s' % (cls.__module__, cls.__name__)) def setUp(self): super(HttpCase, self).setUp() @@ -395,7 +397,7 @@ class HttpCase(TransactionCase): Other lines are relayed to the test log. """ - logger = _logger.getChild('phantomjs') + logger = self._logger.getChild('phantomjs') t0 = datetime.now() td = timedelta(seconds=timeout) buf = bytearray() @@ -1332,10 +1334,11 @@ class TagsSelector(object): tags = getattr(arg, 'test_tags', set()) inter_no_test = self.exclude.intersection(tags) if inter_no_test: - _logger.debug("Test '%s' not selected because of following tag(s): '%s'", arg, inter_no_test) + _logger.debug("Test '%s' not selected because it is tagged with : %s (exclusions: %s)", arg, inter_no_test, self.exclude) return False inter_to_test = self.include.intersection(tags) if not inter_to_test: - _logger.debug("Test '%s' not selected because it was not tagged with '%s'", arg, self.include) + _logger.debug("Test '%s' not selected because it was not tagged with %s", arg, self.include) return False + _logger.debug("Test '%s' selected: tagged with %s, exclusions: %s, inclusions: %s", arg, tags, self.exclude, self.include) return True From 1fe5145f0cc16037d380856dac56545e6c460a3b Mon Sep 17 00:00:00 2001 From: antonylesuisse Date: Thu, 16 Aug 2018 11:45:43 +0200 Subject: [PATCH 02/15] [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/ closes #25991 --- odoo/tests/common.py | 484 +++++++++++++++++++++++++++----------- odoo/tests/phantomtest.js | 145 ------------ 2 files changed, 346 insertions(+), 283 deletions(-) delete mode 100644 odoo/tests/phantomtest.js diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 3579e2f3cd4..73d1a916505 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -4,6 +4,7 @@ The module :mod:`odoo.tests.common` provides unittest test cases and a few helpers and classes to write tests. """ +import base64 import collections import errno import glob @@ -14,16 +15,22 @@ import logging 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 @@ -326,10 +333,282 @@ class SavepointCase(SingleTransactionCase): 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) @@ -341,8 +620,21 @@ class HttpCase(TransactionCase): 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) @@ -362,6 +654,27 @@ class HttpCase(TransactionCase): 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: @@ -385,130 +698,11 @@ class HttpCase(TransactionCase): 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") - - 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 @@ -523,23 +717,37 @@ class HttpCase(TransactionCase): 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) - phantomtest = os.path.join(os.path.dirname(__file__), 'phantomtest.js') - cmd = ['phantomjs', phantomtest, json.dumps(options)] - self.phantom_run(cmd, timeout) + _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 + ) + + # 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 b77cc3ffe9d..00000000000 --- 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); -} From 9211121a57111253f8a426eb6fc87f091b9ac1e8 Mon Sep 17 00:00:00 2001 From: Christophe Monniez Date: Thu, 16 Aug 2018 15:07:43 +0200 Subject: [PATCH 03/15] [FIX] tests: avoid traceback when websocket-client is not installed The account module needs to import Form from "tests.common" causing a traceback when websocket-client module is not installed. As this module is only required for the tests, there is no reason to add it to the "requirements.txt" file. With this commit, Odoo account can be installed even when websocket-client is not installed, in that case, the HttpCase tests that needs to run Chrome headless will be skipped with a warning. Closes: #26404 --- odoo/tests/common.py | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 73d1a916505..cdf81941fa7 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -25,7 +25,6 @@ import tempfile import threading import time import unittest -import websocket import werkzeug.urls from contextlib import contextmanager from datetime import datetime, timedelta, date @@ -43,6 +42,13 @@ try: from itertools import zip_longest as izip_longest except ImportError: from itertools import izip_longest + +try: + import websocket +except ImportError: + # chrome headless tests will be skipped + websocket = None + try: from xmlrpc import client as xmlrpclib except ImportError: @@ -336,6 +342,9 @@ class SavepointCase(SingleTransactionCase): class ChromeBrowser(): def __init__(self): + if websocket is None: + _logger.warning("websocket-client module is not installed") + raise unittest.SkipTest("websocket-client module is not installed") self.devtools_port = PORT + 2 self.ws_url = '' # WebSocketUrl self.ws = None # websocket From 9973994660c73c830ccdeb7497335d60a13a3b3f Mon Sep 17 00:00:00 2001 From: Christophe Monniez Date: Fri, 17 Aug 2018 14:49:53 +0200 Subject: [PATCH 04/15] [FIX] tests: clean the browser even on failure When a Chrome headless test fails the browser is not cleaned and could lead to a mix with other tests when the same method is called. Also, the multiline assertions gives an unreadable message when the assertion fails. Finally, it happens that a thread does not have an 'url' attribute and lead to a crash when the logger tries to show the thread url. With this commit, the browser is cleaned, even on failure and the assertions are now one line. Closes: #26432 --- odoo/tests/common.py | 43 ++++++++++++++++++------------------------- 1 file changed, 18 insertions(+), 25 deletions(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index cdf81941fa7..fcb94dda9d9 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -571,7 +571,6 @@ class ChromeBrowser(): _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') @@ -582,7 +581,6 @@ class ChromeBrowser(): 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')) @@ -675,7 +673,7 @@ class HttpCase(TransactionCase): 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) + thread.name, getattr(thread, 'url', '')) break time.sleep(0.5) t1 = int(time.time()) @@ -730,31 +728,26 @@ class HttpCase(TransactionCase): # 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) + try: + 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) + _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 - ) + # 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) - self.assertTrue( - self.chrome_browser._wait_code_ok(code, timeout), - 'The test code "%s" failed' % code - ) - - # 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() + finally: + # 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 From 614884928e0b4faa4155c37e4bfc8190b235120f Mon Sep 17 00:00:00 2001 From: Raphael Collet Date: Tue, 21 Aug 2018 09:21:11 +0200 Subject: [PATCH 05/15] [FIX] tests: clean up code Closes #26467 --- odoo/tests/common.py | 45 ++++++++++++++++++++++---------------------- 1 file changed, 23 insertions(+), 22 deletions(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index fcb94dda9d9..900bbc327a5 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -340,6 +340,7 @@ class SavepointCase(SingleTransactionCase): class ChromeBrowser(): + """ Helper object to control a Chrome headless process. """ def __init__(self): if websocket is None: @@ -600,7 +601,7 @@ class ChromeBrowser(): _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): + def clear(self): self._websocket_send('Page.stopScreencast') self.screencast_frames = [] self._websocket_send('Page.stopLoading') @@ -611,11 +612,12 @@ class ChromeBrowser(): self._websocket_wait_id(cl_id) self.navigate_to('about:blank', wait_stop=True) + class HttpCase(TransactionCase): """ Transactional HTTP TestCase with url_open and Chrome headless helpers. """ registry_test_mode = True - chrome_browser = None + browser = None def __init__(self, methodName='runTest'): super(HttpCase, self).__init__(methodName) @@ -628,15 +630,16 @@ class HttpCase(TransactionCase): 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() + def start_browser(cls): + # start browser on demand + if cls.browser is None: + cls.browser = ChromeBrowser() @classmethod def tearDownClass(cls): - if cls.chrome_browser: - cls.chrome_browser.stop() - cls.chrome_browser = None + if cls.browser: + cls.browser.stop() + cls.browser = None super(HttpCase, cls).tearDownClass() def setUp(self): @@ -705,9 +708,9 @@ class HttpCase(TransactionCase): 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') + if self.browser: + _logger.info('Setting session cookie in browser') + self.browser.set_cookie('session_id', self.session_id, '/', '127.0.0.1') def browser_js(self, url_path, code, ready='', login=None, timeout=60, **kw): """ Test js code running in the browser @@ -724,29 +727,27 @@ class HttpCase(TransactionCase): If neither are done before timeout test fails. """ - - # Start chrome only if needed (instead of using a setupClass) - self.start_chrome() + self.start_browser() try: self.authenticate(login, login) url = "http://%s:%s%s" % (HOST, PORT, url_path or '/') - _logger.info('Open "%s" in chrome headless' % url) + _logger.info('Open "%s" in browser' % url) _logger.info('Starting screen cast') - self.chrome_browser.start_screencast() - self.chrome_browser.navigate_to(url) + self.browser.start_screencast() + self.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) + self.assertTrue(self.browser._wait_ready(ready), 'The ready "%s" code was always falsy' % ready) + self.assertTrue(self.browser._wait_code_ok(code, timeout), 'The test code "%s" failed' % code) finally: - # better at the end of the method, in case we call the method multiple - # times in the same test - self.chrome_browser.browser_cleanup() + # clear browser to make it stop sending requests, in case we call + # the method several times in a test method + self.browser.clear() self._wait_remaining_requests() phantom_js = browser_js From ecaa04ec824f33279f0fe6aa29e7c73c9c677fce Mon Sep 17 00:00:00 2001 From: Christophe Monniez Date: Wed, 22 Aug 2018 11:28:04 +0200 Subject: [PATCH 06/15] [FIX] tests: increase browser_js ready code timeout Before starting a JS test/tour the _wait_ready method evaluates if the test is ready with a timeout of 10 sec. From times to times, it happens that the page is not ready after this timeout but the problem is hidden. In order to help fixing that kind of issue, the timeout is increased to 60 sec and a warning is logged to emphasis the fact that an issue exists. Also some unused imports are removed with this commit --- odoo/tests/common.py | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 900bbc327a5..2050f25fc55 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -6,8 +6,6 @@ helpers and classes to write tests. """ import base64 import collections -import errno -import glob import importlib import itertools import json @@ -16,19 +14,15 @@ 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 werkzeug.urls from contextlib import contextmanager -from datetime import datetime, timedelta, date -from pprint import pformat +from datetime import datetime, date from decorator import decorator from lxml import etree, html @@ -538,13 +532,15 @@ class ChromeBrowser(): params = {'name': name, 'value': value, 'path': path, 'domain': domain} self._websocket_send('Network.setCookie', params=params) - def _wait_ready(self, ready_code, timeout=10): + def _wait_ready(self, ready_code, timeout=60): _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: + tdiff = time.time() - start_time + has_exceeded = False + while tdiff < timeout: try: res = json.loads(self.ws.recv()) except websocket.WebSocketTimeoutException: @@ -555,6 +551,11 @@ class ChromeBrowser(): else: last_bad_res = res ready_id = self._websocket_send('Runtime.evaluate', params={'expression': ready_code}) + tdiff = time.time() - start_time + if tdiff >= 2 and not has_exceeded: + has_exceeded = True + _logger.warning('The ready code takes too much time : %s' % tdiff) + self.take_screenshot(prefix='failed_ready') _logger.info('Ready code last try result: %s' % last_bad_res or res) return False From 42cfc72d5e205ed0e2697dfa68f52c4caa5cec18 Mon Sep 17 00:00:00 2001 From: Christophe Simonis Date: Thu, 23 Aug 2018 15:20:38 +0200 Subject: [PATCH 07/15] [FIX] core: use actual chrome/chromium executable on macOs. --- odoo/tests/common.py | 37 ++++++++++++++++++++++++++++++++----- 1 file changed, 32 insertions(+), 5 deletions(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 2050f25fc55..2ad90065916 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -12,6 +12,7 @@ import json import logging import operator import os +import platform import re import requests import shutil @@ -30,6 +31,7 @@ from lxml import etree, html from odoo.models import BaseModel from odoo.osv.expression import normalize_domain from odoo.tools import pycompat +from odoo.tools.misc import find_in_path from odoo.tools.safe_eval import safe_eval try: @@ -344,10 +346,10 @@ class ChromeBrowser(): self.ws_url = '' # WebSocketUrl self.ws = None # websocket self.request_id = 0 - self.user_data_dir = '' + self.user_data_dir = tempfile.mkdtemp(suffix='_chrome_odoo') self.chrome_process = None self.screencast_frames = [] - self._chrome_start(['google-chrome'], self.user_data_dir) + self._chrome_start() _logger.info('Websocket url found: %s' % self.ws_url) self._open_websocket() _logger.info('Enable chrome headless console log notification') @@ -367,7 +369,32 @@ class ChromeBrowser(): _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): + @property + def executable(self): + system = platform.system() + if system == 'Linux': + for bin_ in ['google-chrome', 'chromium']: + try: + return find_in_path(bin_) + except IOError: + continue + + elif system == 'Darwin': + bins = [ + '/Applications/Google Chrome.app/Contents/MacOS/Google Chrome', + '/Applications/Chromium.app/Contents/MacOS/Chromium', + ] + for bin_ in bins: + if os.path.exists(bin_): + return bin_ + + elif system == 'Windows': + # TODO: handle windows platform: https://stackoverflow.com/a/40674915 + pass + + raise unittest.SkipTest("Chrome executable not found") + + def _chrome_start(self): if self.chrome_process is not None: return switches = { @@ -376,11 +403,12 @@ class ChromeBrowser(): '--no-default-browser-check': '', '--no-first-run': '', '--disable-extensions': '', - '--user-data-dir': user_data_dir, + '--user-data-dir': self.user_data_dir, '--disable-translate': '', '--window-size': '1366x768', '--remote-debugging-port': str(self.devtools_port) } + cmd = [self.executable] cmd += ['%s=%s' % (k, v) if v else k for k, v in switches.items()] url = 'about:blank' cmd.append(url) @@ -394,7 +422,6 @@ class ChromeBrowser(): _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): From 22dc335803955ab7236c197a66de4161a6391ed5 Mon Sep 17 00:00:00 2001 From: XavierDo Date: Tue, 28 Aug 2018 15:49:11 +0200 Subject: [PATCH 08/15] [FIX] tests, web_tour: improve js error display in build details Since chrome headless has been merged, js error messages are difficult to read: some information was missing or only displayed in full all log. All console.error() will now be displayed in build details, and will appear just before the python assertion. XMO's improvement will also be used on all log: Using module and classname of the class calling phantomJS. Also: some small improvements on error messages to make them easier to read Note: this commit also shown that some error were not detected: now we will fail in any case if js log an error. --- addons/web_tour/static/src/js/tour_manager.js | 3 +- odoo/tests/common.py | 109 ++++++++++-------- 2 files changed, 64 insertions(+), 48 deletions(-) diff --git a/addons/web_tour/static/src/js/tour_manager.js b/addons/web_tour/static/src/js/tour_manager.js index 599e6c6b2f5..7a63edfe342 100644 --- a/addons/web_tour/static/src/js/tour_manager.js +++ b/addons/web_tour/static/src/js/tour_manager.js @@ -437,7 +437,8 @@ return core.Class.extend(mixins.EventDispatcherMixin, ServicesMixin, { console.log(log); }); console.log(document.body.outerHTML); - console.log("error " + error); // phantomJS wait for message starting by error + console.error(error); // will be displayed as error info + console.log("error"); // phantomJS wait for message starting by error to stop } else { console.log(_.str.sprintf("Tour %s succeeded", tour_name)); console.log("ok"); // phantomJS wait for exact message "ok" diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 2ad90065916..80cd8c1e1e8 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -338,9 +338,10 @@ class SavepointCase(SingleTransactionCase): class ChromeBrowser(): """ Helper object to control a Chrome headless process. """ - def __init__(self): + def __init__(self, logger): + self._logger = logger if websocket is None: - _logger.warning("websocket-client module is not installed") + self._logger.warning("websocket-client module is not installed") raise unittest.SkipTest("websocket-client module is not installed") self.devtools_port = PORT + 2 self.ws_url = '' # WebSocketUrl @@ -350,23 +351,23 @@ class ChromeBrowser(): self.chrome_process = None self.screencast_frames = [] self._chrome_start() - _logger.info('Websocket url found: %s' % self.ws_url) + self._logger.info('Websocket url found: %s', self.ws_url) self._open_websocket() - _logger.info('Enable chrome headless console log notification') + self._logger.info('Enable chrome headless console log notification') self._websocket_send('Runtime.enable') - _logger.info('Chrome headless enable page notifications') + self._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._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._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) + self._logger.info('Removing chrome user profile "%s"', self.user_data_dir) shutil.rmtree(self.user_data_dir) @property @@ -412,17 +413,17 @@ class ChromeBrowser(): 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)) + self._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) + self._logger.info('Chrome pid: %s', self.chrome_process.pid) version = self._json_command('version') - _logger.info('Browser version: %s' % version['Browser']) + self._logger.info('Browser version: %s', version['Browser']) infos = self._json_command('')[0] # Infos about the first tab self.ws_url = infos['webSocketDebuggerUrl'] - _logger.info('Chrome headless temporary user profile dir: %s' % self.user_data_dir) + self._logger.info('Chrome headless temporary user profile dir: %s', self.user_data_dir) def _json_command(self, command, timeout=3): """ @@ -436,12 +437,12 @@ class ChromeBrowser(): version : get chrome and dev tools version protocol : get the full protocol """ - _logger.info("Issuing json command %s" % command) + self._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) + self._logger.info('Url : %s', url) r = requests.get(url, timeout=3) if r.ok: return r.json() @@ -451,7 +452,7 @@ class ChromeBrowser(): timeout -= 0.1 except requests.exceptions.ReadTimeout: break - _logger.error('Could not connect to chrome debugger') + self._logger.error('Could not connect to chrome debugger') raise unittest.SkipTest("Cannot connect to chrome headless") def _open_websocket(self): @@ -488,7 +489,7 @@ class ChromeBrowser(): res = None if res and res.get('id') == awaited_id: return res - _logger.info('timeout exceeded while waiting for id : %d' % awaited_id) + self._logger.info('timeout exceeded while waiting for id : %d', awaited_id) return {} def _websocket_wait_event(self, method, params=None, timeout=10): @@ -508,8 +509,8 @@ class ChromeBrowser(): else: return res elif res: - _logger.debug('chrome devtools protocol event: %s' % res) - _logger.info('timeout exceeded while waiting for : %s' % method) + self._logger.debug('chrome devtools protocol event: %s', res) + self._logger.info('timeout exceeded while waiting for : %s', method) def _get_shotname(self, prefix, ext): """ return a unique filename for screenshot or screencast""" @@ -520,23 +521,23 @@ class ChromeBrowser(): def take_screenshot(self, prefix='failed'): if not odoo.tools.config['logfile']: - _logger.info('Screenshot disabled !') + self._logger.info('Screenshot disabled !') return None ss_id = self._websocket_send('Page.captureScreenshot') - _logger.info('Asked for screenshot (id: %s)' % ss_id) + self._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) + self._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 !') + self._logger.info('Screencast disabled !') return None sdir = tempfile.mkdtemp(suffix='_chrome_odoo_screencast') nb = 0 @@ -550,7 +551,7 @@ class ChromeBrowser(): 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) + self._logger.info('Screencast in: %s', outfile) def start_screencast(self): self._websocket_send('Page.startScreencast', {'params': {'everyNthFrame': 5, 'maxWidth': 683, 'maxHeight': 384}}) @@ -560,7 +561,7 @@ class ChromeBrowser(): self._websocket_send('Network.setCookie', params=params) def _wait_ready(self, ready_code, timeout=60): - _logger.info('Evaluate ready code "%s"' % ready_code) + self._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 = '' @@ -581,31 +582,42 @@ class ChromeBrowser(): tdiff = time.time() - start_time if tdiff >= 2 and not has_exceeded: has_exceeded = True - _logger.warning('The ready code takes too much time : %s' % tdiff) + self._logger.warning('The ready code takes too much time : %s', tdiff) self.take_screenshot(prefix='failed_ready') - _logger.info('Ready code last try result: %s' % last_bad_res or res) + self._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) + self._logger.info('Evaluate test code "%s"', code) code_id = self._websocket_send('Runtime.evaluate', params={'expression': code}) start_time = time.time() + logged_error = False 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) + self._logger.info('Code start result: %s', res) if res.get('result', {}).get('result').get('subtype', '') == 'error': - _logger.error("Running code returned an error") + self._logger.error("Running code returned an error") return False - elif res and res.get('method') == 'Runtime.consoleAPICalled' and res.get('params', {}).get('type') == 'log': + elif res and res.get('method') == 'Runtime.consoleAPICalled' and res.get('params', {}).get('type') in ('log', 'error'): logs = res.get('params', {}).get('args') + log_type = res.get('params', {}).get('type') + content = " ".join([str(log.get('value', '')) for log in logs]) + if log_type == 'error': + self._logger.error(content) + logged_error = True + else: + self._logger.info('console log: %s', content) for log in logs: - _logger.info('console logs: %s' % log.get('value', '')) if log.get('type', '') == 'string' and log.get('value', '').lower() == 'ok': + # it is possible that some tests returns ok while an error was shown in logs. + # since runbot should always be red in this case, better explicitly fail. + if logged_error: + return False return True elif log.get('type', '') == 'string' and log.get('value', '').lower().startswith('error'): self.take_screenshot() @@ -614,26 +626,26 @@ class ChromeBrowser(): 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._logger.debug('chrome devtools protocol event: %s', res) + self._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) + self._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) + self._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._logger.info('Waiting for frame "%s" to stop loading', frame_id) self._websocket_wait_event('Page.frameStoppedLoading', params={'frameId': frame_id}) def clear(self): self._websocket_send('Page.stopScreencast') self.screencast_frames = [] self._websocket_send('Page.stopLoading') - _logger.info('Deleting cookies and clearing local storage') + self._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()'}) @@ -658,10 +670,10 @@ class HttpCase(TransactionCase): self._logger = logging.getLogger('%s.%s' % (cls.__module__, cls.__name__)) @classmethod - def start_browser(cls): + def start_browser(cls, logger): # start browser on demand if cls.browser is None: - cls.browser = ChromeBrowser() + cls.browser = ChromeBrowser(logger) @classmethod def tearDownClass(cls): @@ -703,13 +715,13 @@ class HttpCase(TransactionCase): 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", + self._logger.warning("Stop waiting for thread %s handling request for url %s", thread.name, getattr(thread, 'url', '')) break time.sleep(0.5) t1 = int(time.time()) if t0 != t1: - _logger.info('remaining requests') + self._logger.info('remaining requests') odoo.tools.misc.dumpstacks() t0 = t1 @@ -737,7 +749,7 @@ class HttpCase(TransactionCase): odoo.http.root.session_store.save(session) if self.browser: - _logger.info('Setting session cookie in browser') + self._logger.info('Setting session cookie in browser') self.browser.set_cookie('session_id', self.session_id, '/', '127.0.0.1') def browser_js(self, url_path, code, ready='', login=None, timeout=60, **kw): @@ -755,14 +767,14 @@ class HttpCase(TransactionCase): If neither are done before timeout test fails. """ - self.start_browser() + self.start_browser(self._logger) try: self.authenticate(login, login) url = "http://%s:%s%s" % (HOST, PORT, url_path or '/') - _logger.info('Open "%s" in browser' % url) + self._logger.info('Open "%s" in browser', url) - _logger.info('Starting screen cast') + self._logger.info('Starting screen cast') self.browser.start_screencast() self.browser.navigate_to(url) @@ -770,8 +782,11 @@ class HttpCase(TransactionCase): # code = "" ready = ready or "document.readyState === 'complete'" self.assertTrue(self.browser._wait_ready(ready), 'The ready "%s" code was always falsy' % ready) - self.assertTrue(self.browser._wait_code_ok(code, timeout), 'The test code "%s" failed' % code) - + if code: + message = 'The test code "%s" failed' % code + else: + message = "Some js test failed" + self.assertTrue(self.browser._wait_code_ok(code, timeout), message) finally: # clear browser to make it stop sending requests, in case we call # the method several times in a test method From 8a5e40b8752f4ab6e3870c428927c612f203c4af Mon Sep 17 00:00:00 2001 From: Christophe Monniez Date: Fri, 31 Aug 2018 13:47:53 +0200 Subject: [PATCH 09/15] [FIX] tests: redirect chrome headless stdout and stderr to dev null When executing a very long HttpCase browser_js test, it happens that one of the chrome process PIPE is full (ie. clickEverywhere test). In that case, the communication with Chrome is blocked. With this commit the stdout and stderr of the Chrome process are redirected to /dev/null. --- odoo/tests/common.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 80cd8c1e1e8..451d5a1124a 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -415,7 +415,7 @@ class ChromeBrowser(): cmd.append(url) self._logger.info('chrome_run executing %s', ' '.join(cmd)) try: - self.chrome_process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) + self.chrome_process = subprocess.Popen(cmd, stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL) except OSError: raise unittest.SkipTest("%s not found" % cmd[0]) self._logger.info('Chrome pid: %s', self.chrome_process.pid) From 0daf4536a6444c4754940c1d4611316c0cfb84b8 Mon Sep 17 00:00:00 2001 From: Christophe Monniez Date: Tue, 4 Sep 2018 16:56:49 +0200 Subject: [PATCH 10/15] [FIX] tests: disable screencast when no logfile When an HttpCase browser_js test is started, the screencast is started and is discarded at the end of the test if no logfile was provided by the config. This behavior can impact the performances. With this commit, the screencast does not start at all if not needed. --- odoo/tests/common.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 451d5a1124a..32e7a45d5fa 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -774,8 +774,9 @@ class HttpCase(TransactionCase): url = "http://%s:%s%s" % (HOST, PORT, url_path or '/') self._logger.info('Open "%s" in browser', url) - self._logger.info('Starting screen cast') - self.browser.start_screencast() + if odoo.tools.config['logfile']: + self._logger.info('Starting screen cast') + self.browser.start_screencast() self.browser.navigate_to(url) # Needed because tests like test01.js (qunit tests) are passing a ready From 5a523b06cde9a9e21775ee156df91edeb04d745d Mon Sep 17 00:00:00 2001 From: Christophe Monniez Date: Tue, 28 Aug 2018 10:28:02 +0200 Subject: [PATCH 11/15] [FIX] tests: properly stop chrome when no tab found In some situations, Chrome remote debugging is sending an empty list of opened tabs. In that case, an orphan Chrome process stays alive. With this commit, Chrome is stopped properly in those situations. --- odoo/tests/common.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 32e7a45d5fa..b786f4117d0 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -351,6 +351,7 @@ class ChromeBrowser(): self.chrome_process = None self.screencast_frames = [] self._chrome_start() + self._find_websocket() self._logger.info('Websocket url found: %s', self.ws_url) self._open_websocket() self._logger.info('Enable chrome headless console log notification') @@ -419,9 +420,16 @@ class ChromeBrowser(): except OSError: raise unittest.SkipTest("%s not found" % cmd[0]) self._logger.info('Chrome pid: %s', self.chrome_process.pid) + + def _find_websocket(self): version = self._json_command('version') self._logger.info('Browser version: %s', version['Browser']) - infos = self._json_command('')[0] # Infos about the first tab + try: + infos = self._json_command('')[0] # Infos about the first tab + except IndexError: + self._logger.warning('No tab found in Chrome') + self.stop() + raise unittest.SkipTest('No tab found in Chrome') self.ws_url = infos['webSocketDebuggerUrl'] self._logger.info('Chrome headless temporary user profile dir: %s', self.user_data_dir) From 383ed26657754fb71d35e9f9014a600d273a9d8a Mon Sep 17 00:00:00 2001 From: Christophe Monniez Date: Tue, 28 Aug 2018 15:12:01 +0200 Subject: [PATCH 12/15] [FIX] tests: close Chrome and shutdown on SIGXCPU When Odoo receive a SIGXCPU (CPU time limit reached), it shuts down immediately. If a headless Chrome is running, it stays alive after the Odoo shutdown. With this commit, the signal is intercepeted and the Chrome browser is properly closed before shutting down the Odoo server. --- odoo/tests/common.py | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index b786f4117d0..093614c5dfa 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -16,6 +16,7 @@ import platform import re import requests import shutil +import signal import subprocess import tempfile import threading @@ -358,6 +359,16 @@ class ChromeBrowser(): self._websocket_send('Runtime.enable') self._logger.info('Chrome headless enable page notifications') self._websocket_send('Page.enable') + self.sigxcpu_handler = None + if os.name == 'posix': + self.sigxcpu_handler = signal.getsignal(signal.SIGXCPU) + signal.signal(signal.SIGXCPU, self.signal_handler) + + def signal_handler(self, sig, frame): + if sig == signal.SIGXCPU: + _logger.info('CPU time limit reached, stopping Chrome and shutting down') + self.stop() + os._exit(0) def stop(self): if self.chrome_process is not None: @@ -370,6 +381,9 @@ class ChromeBrowser(): if self.user_data_dir and os.path.isdir(self.user_data_dir) and self.user_data_dir != '/': self._logger.info('Removing chrome user profile "%s"', self.user_data_dir) shutil.rmtree(self.user_data_dir) + # Restore previous signal handler + if self.sigxcpu_handler and os.name == 'posix': + signal.signal(signal.SIGXCPU, self.sigxcpu_handler) @property def executable(self): From 2f63e1e973fdca02eb854b1e83263a4e901f340d Mon Sep 17 00:00:00 2001 From: Christophe Monniez Date: Tue, 28 Aug 2018 16:22:50 +0200 Subject: [PATCH 13/15] [FIX] tests: detect coverage and adjust timeout When computing coverage, the tests are slowed down and the timeout is often exceeded. With this commit, HttpCase headless Chrome tests timeout is increased if coverage is detected. --- odoo/tests/common.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 093614c5dfa..64659538162 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -7,6 +7,7 @@ helpers and classes to write tests. import base64 import collections import importlib +import inspect import itertools import json import logging @@ -789,6 +790,9 @@ class HttpCase(TransactionCase): If neither are done before timeout test fails. """ + # increase timeout if coverage is running + if any(f.filename.endswith('/coverage/execfile.py') for f in inspect.stack() if f.filename): + timeout = timeout * 1.5 self.start_browser(self._logger) try: From 0e388750c120582c54cec26fe016fe96ed8f334d Mon Sep 17 00:00:00 2001 From: Denis Ledoux Date: Fri, 14 Sep 2018 10:41:55 +0200 Subject: [PATCH 14/15] [FIX] tests: chromium executable is chromium-browser When installing chromium using apt e.g apt install chromium-browser the executable is `chromium-browser`, not just `chromium` --- odoo/tests/common.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 64659538162..89bf9158814 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -390,7 +390,7 @@ class ChromeBrowser(): def executable(self): system = platform.system() if system == 'Linux': - for bin_ in ['google-chrome', 'chromium']: + for bin_ in ['google-chrome', 'chromium-browser']: try: return find_in_path(bin_) except IOError: From 8f8060faae8a26784baa288f7722f322200faf62 Mon Sep 17 00:00:00 2001 From: Denis Ledoux Date: Fri, 14 Sep 2018 11:27:45 +0200 Subject: [PATCH 15/15] [FIX] tests: web tests, chromium fallback On Ubuntu, the chromium executable is `chromium-browser`, On other distributions, such as debian, it's `chromium`. We therefore add another fallback --- odoo/tests/common.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 89bf9158814..9ee1def1aac 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -390,7 +390,7 @@ class ChromeBrowser(): def executable(self): system = platform.system() if system == 'Linux': - for bin_ in ['google-chrome', 'chromium-browser']: + for bin_ in ['google-chrome', 'chromium', 'chromium-browser']: try: return find_in_path(bin_) except IOError: