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