[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
This commit is contained in:
antonylesuisse
2018-10-18 11:59:38 +02:00
committed by Christophe Simonis
parent 35eaa523bd
commit 1fe5145f0c
2 changed files with 346 additions and 283 deletions
+346 -138
View File
@@ -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'<phantomLog>') or b'</phantomLog>' in buf):
if buf.startswith(b'<phantomLog>'):
line, buf = buf[12:].split(b'</phantomLog>\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. """
-145
View File
@@ -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('<phantomLog>'+message+'</phantomLog>');
};
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('<phantomLog>error ' + message + '</phantomLog>');
});
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);
}