diff --git a/components/net/websocket_loader.rs b/components/net/websocket_loader.rs index 77140631e7a5..83d9173f78d8 100644 --- a/components/net/websocket_loader.rs +++ b/components/net/websocket_loader.rs @@ -40,14 +40,16 @@ pub fn init( http_state: Arc ) { thread::Builder::new().name(format!("WebSocket connection to {}", req_init.url)).spawn(move || { + let url = req_init.url.clone(); let channel = establish_a_websocket_connection(req_init, &http_state); let (ws_sender, mut receiver) = match channel { Ok((protocol_in_use, sender, receiver)) => { + debug!("Established a websocket connection"); let _ = resource_event_sender.send(WebSocketNetworkEvent::ConnectionEstablished { protocol_in_use }); (sender, receiver) }, Err(e) => { - debug!("Failed to establish a WebSocket connection: {:?}", e); + debug!("Failed to establish a WebSocket connection to {}: {:?}", url, e); let _ = resource_event_sender.send(WebSocketNetworkEvent::Fail); return; } @@ -122,6 +124,7 @@ type Stream = HttpStream; // https://fetch.spec.whatwg.org/#concept-websocket-connection-obtain fn obtain_a_websocket_connection(url: &ServoUrl) -> Result { + //debug!("about to obtain connection"); // Step 1. let host = url.host_str().unwrap(); @@ -143,9 +146,11 @@ fn obtain_a_websocket_connection(url: &ServoUrl) -> Result // Steps 4-5. let host = replace_host(host); + debug!("making TCP connection to {}:{}", host, port); let tcp_stream = TcpStream::connect((&*host, port)).map_err(|e| { NetworkError::Internal(format!("Could not connect to host: {}", e)) })?; + //debug!("made TCP connection to {}:{}", host, port); Ok(HttpStream(tcp_stream)) } diff --git a/etc/ci/buildbot_steps.yml b/etc/ci/buildbot_steps.yml index 217c409b27b1..53c81d2da656 100644 --- a/etc/ci/buildbot_steps.yml +++ b/etc/ci/buildbot_steps.yml @@ -1,5 +1,6 @@ env: RUST_BACKTRACE: '1' + RUST_LOG: 'net::websocket_loader,websocket' RUSTFLAGS: -Dwarnings CARGO_INCREMENTAL: "0" SCCACHE_IDLE_TIMEOUT: "1200" @@ -7,37 +8,34 @@ env: mac-rel-wpt1: - ./mach clean-nightlies --keep 3 --force - ./mach clean-cargo-cache --keep 3 --force - - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --release - - ./mach run -r -o output.png + - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --dev + - ./mach run -d -o output.png - ./mach test-wpt-failure - - ./mach test-wpt --release --processes 4 --total-chunks 6 --this-chunk 1 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed + - ./mach test-wpt --processes 4 --total-chunks 6 --this-chunk 1 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed - ./mach filter-intermittents wpt-errorsummary.log --log-intermittents intermittents.log --log-filteredsummary filtered-wpt-errorsummary.log --tracker-api default --reporter-api default - - ./mach test-wpt --release --binary-arg=--multiprocess --processes 8 --log-raw test-wpt-mp.log --log-errorsummary wpt-mp-errorsummary.log eventsource - bash ./etc/ci/lockfile_changed.sh - bash ./etc/ci/manifest_changed.sh mac-rel-wpt2: - ./mach clean-nightlies --keep 3 --force - ./mach clean-cargo-cache --keep 3 --force - - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --release - - ./mach test-wpt --release --processes 4 --total-chunks 6 --this-chunk 2 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed + - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --dev + - ./mach test-wpt --processes 4 --total-chunks 6 --this-chunk 2 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed - ./mach filter-intermittents wpt-errorsummary.log --log-intermittents intermittents.log --log-filteredsummary filtered-wpt-errorsummary.log --tracker-api default --reporter-api default mac-rel-wpt3: - ./mach clean-nightlies --keep 3 --force - ./mach clean-cargo-cache --keep 3 --force - - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --release - - ./mach test-wpt --release --processes 4 --total-chunks 6 --this-chunk 3 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed + - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --dev + - ./mach test-wpt --processes 4 --total-chunks 6 --this-chunk 3 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed - ./mach filter-intermittents wpt-errorsummary.log --log-intermittents intermittents.log --log-filteredsummary filtered-wpt-errorsummary.log --tracker-api default --reporter-api default mac-rel-wpt4: - ./mach clean-nightlies --keep 3 --force - ./mach clean-cargo-cache --keep 3 --force - - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --release - - ./mach test-wpt --release --processes 4 --total-chunks 6 --this-chunk 4 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed + - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --dev + - ./mach test-wpt --processes 4 --total-chunks 6 --this-chunk 4 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed - ./mach filter-intermittents wpt-errorsummary.log --log-intermittents intermittents.log --log-filteredsummary filtered-wpt-errorsummary.log --tracker-api default --reporter-api default - - ./mach test-wpt --release --pref dom.servoparser.async_html_tokenizer.enabled --processes=8 --log-raw test-async-parsing.log --log-errorsummary async-parsing-errorsummary.log --always-succeed domparsing html/syntax html/dom/documents html/dom/dynamic-markup-insertion - - ./mach filter-intermittents async-parsing-errorsummary.log --log-intermittents async-parsing-intermittents.log --log-filteredsummary filtered-async-parsing-errorsummary.log --tracker-api default --reporter-api default mac-dev-unit: - ./mach clean-nightlies --keep 3 --force @@ -52,8 +50,8 @@ mac-dev-unit: mac-rel-css1: - ./mach clean-nightlies --keep 3 --force - ./mach clean-cargo-cache --keep 3 --force - - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --release - - ./mach test-wpt --release --processes 4 --total-chunks 6 --this-chunk 5 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed + - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --dev + - ./mach test-wpt --processes 4 --total-chunks 6 --this-chunk 5 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed - ./mach filter-intermittents wpt-errorsummary.log --log-intermittents intermittents.log --log-filteredsummary filtered-wpt-errorsummary.log --tracker-api default --reporter-api default - bash ./etc/ci/lockfile_changed.sh - bash ./etc/ci/manifest_changed.sh @@ -61,8 +59,8 @@ mac-rel-css1: mac-rel-css2: - ./mach clean-nightlies --keep 3 --force - ./mach clean-cargo-cache --keep 3 --force - - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --release - - ./mach test-wpt --release --processes 4 --total-chunks 6 --this-chunk 6 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed + - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --dev + - ./mach test-wpt --processes 4 --total-chunks 6 --this-chunk 6 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed - ./mach filter-intermittents wpt-errorsummary.log --log-intermittents intermittents.log --log-filteredsummary filtered-wpt-errorsummary.log --tracker-api default --reporter-api default mac-nightly: @@ -71,9 +69,6 @@ mac-nightly: - env PKG_CONFIG_PATH=/usr/local/opt/zlib/lib/pkgconfig ./mach build --release - ./mach package --release - ./mach upload-nightly mac - - ./etc/ci/update-wpt-checkout fetch-and-update-expectations - - ./etc/ci/update-wpt-checkout open-pr - - ./etc/ci/update-wpt-checkout cleanup linux-rel-intermittent: - ./mach clean-nightlies --keep 3 --force @@ -124,11 +119,10 @@ linux-rel-wpt: - ./mach clean-nightlies --keep 3 --force - ./mach clean-cargo-cache --keep 3 --force - ./etc/ci/clean_build_artifacts.sh - - ./mach build --release --with-debug-assertions + - ./mach build --dev --with-debug-assertions - ./mach test-wpt-failure - - ./mach test-wpt --release --processes 24 --total-chunks 2 --this-chunk 1 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed + - ./mach test-wpt --processes 24 --total-chunks 2 --this-chunk 1 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed - ./mach filter-intermittents wpt-errorsummary.log --log-intermittents intermittents.log --log-filteredsummary filtered-wpt-errorsummary.log --tracker-api default --reporter-api default - - ./mach test-wpt --release --binary-arg=--multiprocess --processes 24 --log-raw test-wpt-mp.log --log-errorsummary wpt-mp-errorsummary.log eventsource linux-rel-css: env: @@ -138,8 +132,8 @@ linux-rel-css: - ./mach clean-nightlies --keep 3 --force - ./mach clean-cargo-cache --keep 3 --force - ./etc/ci/clean_build_artifacts.sh - - ./mach build --release --with-debug-assertions - - ./mach test-wpt --release --processes 24 --total-chunks 2 --this-chunk 2 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed + - ./mach build --dev --with-debug-assertions + - ./mach test-wpt --processes 24 --total-chunks 2 --this-chunk 2 --log-raw test-wpt.log --log-errorsummary wpt-errorsummary.log --always-succeed - ./mach filter-intermittents wpt-errorsummary.log --log-intermittents intermittents.log --log-filteredsummary filtered-wpt-errorsummary.log --tracker-api default --reporter-api default - bash ./etc/ci/lockfile_changed.sh - bash ./etc/ci/manifest_changed.sh diff --git a/tests/wpt/include.ini b/tests/wpt/include.ini index 8e703e62c7e5..5e58338a78a2 100644 --- a/tests/wpt/include.ini +++ b/tests/wpt/include.ini @@ -1,117 +1,3 @@ skip: true -[_mozilla] - skip: false -[2dcontext] - skip: false -[cors] - skip: false -[css] - skip: true - [compositing] - skip: false - [CSS2] - skip: false - [css-animations] - skip: false - [css-backgrounds] - skip: false - [css-color] - skip: false - [css-conditional] - skip: false - [css-flexbox] - skip: false - [css-fonts] - skip: false - [css-images] - skip: false - [css-paint-api] - skip: false - [css-style-attr] - skip: false - [css-text] - skip: false - [css-text-decor] - skip: false - [css-transforms] - skip: false - [css-transitions] - skip: false - [css-ui] - skip: false - [css-values] - skip: false - [css-variables] - skip: false - [cssom] - skip: false - [cssom-view] - skip: false - [filter-effects] - skip: false - [geometry] - skip: false - [mediaqueries] - skip: false - [selectors] - skip: false -[custom-elements] - skip: false -[dom] - skip: false -[domparsing] - skip: false -[encoding] - skip: false -[eventsource] - skip: false -[fetch] - skip: false -[FileAPI] - skip: false -[fullscreen] - skip: false -[gamepad] - skip: false -[hr-time] - skip: false -[html] - skip: false -[js] - skip: false -[navigation-timing] - skip: false -[old-tests] - skip: true - [submission] - skip: true -[performance-timeline] - skip: false -[quirks] - skip: false -[referrer-policy] - skip: false -[subresource-integrity] - skip: false -[touch-events] - skip: false -[uievents] - skip: false -[url] - skip: false -[WebCryptoAPI] - skip: false -[webgl] - skip: false -[webvr] - skip: false -[WebIDL] - skip: false [websockets] - skip: false -[webstorage] - skip: false -[workers] - skip: false -[xhr] - skip: false + skip: false \ No newline at end of file diff --git a/tests/wpt/web-platform-tests/tools/pywebsocket/mod_pywebsocket/standalone.py b/tests/wpt/web-platform-tests/tools/pywebsocket/mod_pywebsocket/standalone.py index 63200e235c72..1b1f86556d7d 100755 --- a/tests/wpt/web-platform-tests/tools/pywebsocket/mod_pywebsocket/standalone.py +++ b/tests/wpt/web-platform-tests/tools/pywebsocket/mod_pywebsocket/standalone.py @@ -563,10 +563,13 @@ def get_request(self): attribute. """ + self._logger.info('Accepting a socket') accepted_socket, client_address = self.socket.accept() + self._logger.info('Accepted a socket') server_options = self.websocket_server_options if server_options.use_tls: + #self._logger.info('Performing TLS steps') if server_options.tls_module == _TLS_BY_STANDARD_MODULE: try: accepted_socket.do_handshake() @@ -629,6 +632,7 @@ def serve_forever(self, poll_interval=0.5): self.__ws_serving = True self.__ws_is_shut_down.clear() + self._logger.info('Starting to serve forever') handle_request = self.handle_request if hasattr(self, '_handle_request_noblock'): handle_request = self._handle_request_noblock @@ -640,17 +644,22 @@ def serve_forever(self, poll_interval=0.5): [socket_[0] for socket_ in self._sockets], [], [], poll_interval) for socket_ in r: + #self._logger.info('Socket selected; handling request') self.socket = socket_ handle_request() + #self._logger.info('Handled request') self.socket = None finally: + self._logger.info('Marking shutdown; no longer serving forever') self.__ws_is_shut_down.set() def shutdown(self): """Override SocketServer.BaseServer.shutdown.""" + self._logger.info('Shutting down') self.__ws_serving = False self.__ws_is_shut_down.wait() + self._logger.info('Finished shutting down') class WebSocketRequestHandler(CGIHTTPServer.CGIHTTPRequestHandler): @@ -705,6 +714,7 @@ def parse_request(self): this method to understand how the return value will be handled. """ + self._logger.info('Parsing a request') # We hook parse_request method, but also call the original # CGIHTTPRequestHandler.parse_request since when we return False, # CGIHTTPRequestHandler.handle_one_request continues processing and diff --git a/tests/wpt/web-platform-tests/tools/serve/serve.py b/tests/wpt/web-platform-tests/tools/serve/serve.py index 0fd5f907e964..028d1f406fd5 100644 --- a/tests/wpt/web-platform-tests/tools/serve/serve.py +++ b/tests/wpt/web-platform-tests/tools/serve/serve.py @@ -22,6 +22,7 @@ from six.moves import reload_module from manifest.sourcefile import read_script_metadata, js_meta_re, parse_variants +from wptrunner import wptlogging from wptserve import server as wptserve, handlers from wptserve import stash from wptserve import config @@ -356,19 +357,19 @@ def __init__(self): self.stop = Event() def start(self, init_func, host, port, paths, routes, bind_address, config, - ssl_config, **kwargs): + ssl_config, logging_queue, **kwargs): self.proc = Process(target=self.create_daemon, args=(init_func, host, port, paths, routes, bind_address, - config, ssl_config), + config, ssl_config, logging_queue), kwargs=kwargs) self.proc.daemon = True self.proc.start() def create_daemon(self, init_func, host, port, paths, routes, bind_address, - config, ssl_config, **kwargs): + config, ssl_config, logging_queue, **kwargs): try: self.daemon = init_func(host, port, paths, routes, bind_address, config, - ssl_config, **kwargs) + ssl_config, logging_queue, **kwargs) except socket.error: print("Socket error on port %s" % port, file=sys.stderr) raise @@ -400,7 +401,7 @@ def is_alive(self): return self.proc.is_alive() -def check_subdomains(config): +def check_subdomains(config, logging_queue): paths = config.paths bind_address = config.bind_address ssl_config = config.ssl_config @@ -412,7 +413,7 @@ def check_subdomains(config): wrapper = ServerProc() wrapper.start(start_http_server, host, port, paths, build_routes(aliases), bind_address, - None, ssl_config) + None, ssl_config, logging_queue) connected = False for i in range(10): @@ -463,7 +464,7 @@ def make_hosts_file(config, host): def start_servers(host, ports, paths, routes, bind_address, config, ssl_config, - **kwargs): + logging_queue, **kwargs): servers = defaultdict(list) for scheme, ports in ports.iteritems(): assert len(ports) == {"http":2}.get(scheme, 1) @@ -478,14 +479,19 @@ def start_servers(host, ports, paths, routes, bind_address, config, ssl_config, server_proc = ServerProc() server_proc.start(init_func, host, port, paths, routes, bind_address, - config, ssl_config, **kwargs) + config, ssl_config, logging_queue, **kwargs) servers[scheme].append((port, server_proc)) return servers -def start_http_server(host, port, paths, routes, bind_address, config, ssl_config, +def start_http_server(host, port, paths, routes, bind_address, config, ssl_config, logging_queue, **kwargs): + if logging_queue: + root_logger = logging.getLogger() + root_logger.setLevel(logging.INFO) + root_logger.addHandler(wptlogging.StdQueueHandler(logging_queue, component="wptserve:http")) + return wptserve.WebTestHttpd(host=host, port=port, doc_root=paths["doc_root"], @@ -499,8 +505,13 @@ def start_http_server(host, port, paths, routes, bind_address, config, ssl_confi latency=kwargs.get("latency")) -def start_https_server(host, port, paths, routes, bind_address, config, ssl_config, +def start_https_server(host, port, paths, routes, bind_address, config, ssl_config, logging_queue, **kwargs): + if logging_queue: + root_logger = logging.getLogger() + root_logger.setLevel(logging.INFO) + root_logger.addHandler(wptlogging.StdQueueHandler(logging_queue, component="wptserve:https")) + return wptserve.WebTestHttpd(host=host, port=port, doc_root=paths["doc_root"], @@ -517,7 +528,7 @@ def start_https_server(host, port, paths, routes, bind_address, config, ssl_conf class WebSocketDaemon(object): def __init__(self, host, port, doc_root, handlers_root, log_level, bind_address, - ssl_config): + ssl_config, logging_queue): self.host = host cmd_args = ["-p", port, "-d", doc_root, @@ -546,6 +557,14 @@ def __init__(self, host, port, doc_root, handlers_root, log_level, bind_address, opts, args = pywebsocket._parse_args_and_config(cmd_args) opts.cgi_directories = [] opts.is_executable_method = None + + if logging_queue: + root_logger = logging.getLogger() + root_logger.addHandler(wptlogging.StdQueueHandler( + logging_queue, + component="pywebsocket:%s" % ("wss" if ssl_config else "ws"))) + root_logger.setLevel(logging.getLevelName(opts.log_level.upper())) + self.server = pywebsocket.WebSocketServer(opts) ports = [item[0].getsockname()[1] for item in self.server._sockets] assert all(item == ports[0] for item in ports) @@ -580,35 +599,39 @@ def stop(self): self.server = None -def start_ws_server(host, port, paths, routes, bind_address, config, ssl_config, +def start_ws_server(host, port, paths, routes, bind_address, config, ssl_config, logging_queue, **kwargs): # Ensure that when we start this in a new process we don't inherit the # global lock in the logging module reload_module(logging) + reload_module(wptlogging) return WebSocketDaemon(host, str(port), repo_root, paths["ws_doc_root"], "debug", bind_address, - ssl_config = None) + ssl_config = None, + logging_queue=logging_queue) -def start_wss_server(host, port, paths, routes, bind_address, config, ssl_config, +def start_wss_server(host, port, paths, routes, bind_address, config, ssl_config, logging_queue, **kwargs): # Ensure that when we start this in a new process we don't inherit the # global lock in the logging module reload_module(logging) + reload_module(wptlogging) return WebSocketDaemon(host, str(port), repo_root, paths["ws_doc_root"], "debug", bind_address, - ssl_config) + ssl_config, + logging_queue=logging_queue) -def start(config, ssl_environment, routes, **kwargs): +def start(config, ssl_environment, routes, logging_queue, **kwargs): host = config["server_host"] ports = config.ports paths = config.paths @@ -618,7 +641,7 @@ def start(config, ssl_environment, routes, **kwargs): logger.debug("Using ports: %r" % ports) servers = start_servers(host, ports, paths, routes, bind_address, config, - ssl_config, **kwargs) + ssl_config, logging_queue, **kwargs) return servers @@ -757,8 +780,9 @@ def run(**kwargs): bind_address = config["bind_address"] + if config["check_subdomains"]: - check_subdomains(config) + check_subdomains(config, logging_queue=None) stash_address = None if bind_address: @@ -766,7 +790,8 @@ def run(**kwargs): logger.debug("Going to use port %d for stash" % stash_address[1]) with stash.StashServer(stash_address, authkey=str(uuid.uuid4())): - servers = start(config, config.ssl_env, build_routes(config["aliases"]), **kwargs) + servers = start(config, config.ssl_env, build_routes(config["aliases"]), logging_queue=None, + **kwargs) try: while any(item.is_alive() for item in iter_procs(servers)): diff --git a/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/environment.py b/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/environment.py index 309174c42e65..d23eab40a11b 100644 --- a/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/environment.py +++ b/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/environment.py @@ -64,9 +64,10 @@ class TestEnvironmentError(Exception): class TestEnvironment(object): - def __init__(self, test_paths, ssl_env, pause_after_test, debug_info, options, env_extras): + def __init__(self, logging_queue, test_paths, ssl_env, pause_after_test, debug_info, options, env_extras): """Context manager that owns the test environment i.e. the http and websockets servers""" + self.logging_queue = logging_queue self.test_paths = test_paths self.ssl_env = ssl_env self.server = None @@ -102,7 +103,8 @@ def __enter__(self): self.servers = serve.start(self.config, self.ssl_env, - self.get_routes()) + self.get_routes(), + self.logging_queue) if self.options.get("supports_debugger") and self.debug_info and self.debug_info.interactive: self.ignore_interrupts() return self diff --git a/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptlogging.py b/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptlogging.py index 26d174c066bc..4c15f42428a0 100644 --- a/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptlogging.py +++ b/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptlogging.py @@ -1,12 +1,12 @@ import logging import sys import threading -from Queue import Empty from StringIO import StringIO from multiprocessing import Queue -from mozlog import commandline, stdadapter, set_default_logger -from mozlog.structuredlog import StructuredLogger +from mozlog import commandline, get_default_logger, stdadapter, set_default_logger +from mozlog.structuredlog import StructuredLogger, log_levels + def setup(args, defaults): logger = args.pop('log', None) @@ -53,32 +53,41 @@ def __call__(self, data): class LogThread(threading.Thread): - def __init__(self, queue, logger, level): + def __init__(self, queue, logger): + assert logger.component is None self.queue = queue - self.log_func = getattr(logger, level) + self.loggers = {None: logger} threading.Thread.__init__(self, name="Thread-Log") self.daemon = True + def get_logger(self, component=None): + if component not in self.loggers: + name = self.loggers[None].name + self.loggers[component] = StructuredLogger(name, component) + return self.loggers[component] + def run(self): while True: try: - msg = self.queue.get() + command = self.queue.get() except (EOFError, IOError): break - if msg is None: + if command is None: break else: - self.log_func(msg) + component, level, msg = command + getattr(self.get_logger(component), level)(msg) -class LoggingWrapper(StringIO): +class FileLogging(StringIO): """Wrapper for file like objects to redirect output to logger instead""" - def __init__(self, queue, prefix=None): + def __init__(self, queue, prefix=None, level="info"): StringIO.__init__(self) self.queue = queue self.prefix = prefix + self.level = level def write(self, data): if isinstance(data, str): @@ -95,41 +104,69 @@ def write(self, data): return if self.prefix is not None: data = "%s: %s" % (self.prefix, data) - self.queue.put(data) + self.queue.put((None, self.level, data)) def flush(self): pass class CaptureIO(object): - def __init__(self, logger, do_capture): - self.logger = logger + def __init__(self, queue, do_capture): + self.logging_queue = queue self.do_capture = do_capture - self.logging_queue = None - self.logging_thread = None self.original_stdio = None def __enter__(self): if self.do_capture: self.original_stdio = (sys.stdout, sys.stderr) - self.logging_queue = Queue() - self.logging_thread = LogThread(self.logging_queue, self.logger, "info") - sys.stdout = LoggingWrapper(self.logging_queue, prefix="STDOUT") - sys.stderr = LoggingWrapper(self.logging_queue, prefix="STDERR") - self.logging_thread.start() + sys.stdout = FileLogging(self.logging_queue, prefix="STDOUT") + sys.stderr = FileLogging(self.logging_queue, prefix="STDERR") def __exit__(self, *args, **kwargs): if self.do_capture: sys.stdout, sys.stderr = self.original_stdio - if self.logging_queue is not None: - self.logger.info("Closing logging queue") - self.logging_queue.put(None) - if self.logging_thread is not None: - self.logging_thread.join(10) - while not self.logging_queue.empty(): - try: - self.logger.warning("Dropping log message: %r", self.logging_queue.get()) - except Exception: - pass - self.logging_queue.close() - self.logger.info("queue closed") + + +class StdQueueHandler(logging.Handler): + def __init__(self, queue, component=None, level=logging.NOTSET): + super(StdQueueHandler, self).__init__(level=level) + self.component = component + self.queue = queue + + def emit(self, record): + if record.levelname in log_levels: + level = record.levelname.lower() + else: + level = "debug" + msg = record.msg + if record.args: + msg = msg % record.args + self.queue.put((self.component, level, msg)) + + def handle(self, record): + self.emit(record) + + +class LoggingQueue(object): + def __init__(self, logger): + self.logger = logger + self.queue = Queue() + self.thread = None + + def __enter__(self): + self.thread = LogThread(self.queue, self.logger) + self.thread.start() + return self.queue + + def __exit__(self, *args, **kwargs): + self.logger.info("Closing logging queue") + self.queue.put(None) + if self.thread is not None: + self.thread.join(10) + while not self.queue.empty(): + try: + self.logger.warning("Dropping log message: %r", self.queue.get()) + except Exception: + pass + self.queue.close() + self.logger.info("queue closed") diff --git a/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptrunner.py b/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptrunner.py index bd2b3ad23bd0..0b31668f7f44 100644 --- a/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptrunner.py +++ b/tests/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptrunner.py @@ -135,159 +135,161 @@ def get_pause_after_test(test_loader, **kwargs): def run_tests(config, test_paths, product, **kwargs): - with wptlogging.CaptureIO(logger, not kwargs["no_capture_stdio"]): - env.do_delayed_imports(logger, test_paths) - - (check_args, - target_browser_cls, get_browser_kwargs, - executor_classes, get_executor_kwargs, - env_options, get_env_extras, run_info_extras) = products.load_product(config, product) - - ssl_env = env.ssl_env(logger, **kwargs) - env_extras = get_env_extras(**kwargs) - - check_args(**kwargs) - - if kwargs["install_fonts"]: - env_extras.append(FontInstaller( - font_dir=kwargs["font_dir"], - ahem=os.path.join(kwargs["tests_root"], "fonts/Ahem.ttf") - )) - - if "test_loader" in kwargs: - run_info = wpttest.get_run_info(kwargs["run_info"], product, - browser_version=kwargs.get("browser_version"), - debug=None, - extras=run_info_extras(**kwargs)) - test_loader = kwargs["test_loader"] - else: - run_info, test_loader = get_loader(test_paths, - product, - ssl_env, - run_info_extras=run_info_extras(**kwargs), - **kwargs) - - test_source_kwargs = {"processes": kwargs["processes"]} - if kwargs["run_by_dir"] is False: - test_source_cls = testloader.SingleTestSource - else: - # A value of None indicates infinite depth - test_source_cls = testloader.PathGroupedSource - test_source_kwargs["depth"] = kwargs["run_by_dir"] - - logger.info("Using %i client processes" % kwargs["processes"]) - - test_total = 0 - unexpected_total = 0 - - kwargs["pause_after_test"] = get_pause_after_test(test_loader, **kwargs) - - with env.TestEnvironment(test_paths, - ssl_env, - kwargs["pause_after_test"], - kwargs["debug_info"], - env_options, - env_extras) as test_environment: - try: - test_environment.ensure_started() - except env.TestEnvironmentError as e: - logger.critical("Error starting test environment: %s" % e.message) - raise - - repeat = kwargs["repeat"] - repeat_count = 0 - repeat_until_unexpected = kwargs["repeat_until_unexpected"] - - while repeat_count < repeat or repeat_until_unexpected: - repeat_count += 1 - if repeat_until_unexpected: - logger.info("Repetition %i" % (repeat_count)) - elif repeat > 1: - logger.info("Repetition %i / %i" % (repeat_count, repeat)) - - test_count = 0 - unexpected_count = 0 - logger.suite_start(test_loader.test_ids, name='web-platform-test', run_info=run_info) - for test_type in kwargs["test_types"]: - logger.info("Running %s tests" % test_type) - - # WebDriver tests may create and destroy multiple browser - # processes as part of their expected behavior. These - # processes are managed by a WebDriver server binary. This - # obviates the need for wptrunner to provide a browser, so - # the NullBrowser is used in place of the "target" browser - if test_type == "wdspec": - browser_cls = NullBrowser - else: - browser_cls = target_browser_cls - - browser_kwargs = get_browser_kwargs(test_type, - run_info, - ssl_env=ssl_env, - config=test_environment.config, - **kwargs) - - executor_cls = executor_classes.get(test_type) - executor_kwargs = get_executor_kwargs(test_type, - test_environment.config, - test_environment.cache_manager, - run_info, - **kwargs) - - if executor_cls is None: - logger.error("Unsupported test type %s for product %s" % - (test_type, product)) - continue - - for test in test_loader.disabled_tests[test_type]: - logger.test_start(test.id) - logger.test_end(test.id, status="SKIP") - - if test_type == "testharness": - run_tests = {"testharness": []} - for test in test_loader.tests["testharness"]: - if test.testdriver and not executor_cls.supports_testdriver: - logger.test_start(test.id) - logger.test_end(test.id, status="SKIP") - elif test.jsshell and not executor_cls.supports_jsshell: - # We expect that tests for JavaScript shells - # will not be run along with tests that run in - # a full web browser, so we silently skip them - # here. - pass - else: - run_tests["testharness"].append(test) - else: - run_tests = test_loader.tests - - with ManagerGroup("web-platform-tests", - kwargs["processes"], - test_source_cls, - test_source_kwargs, - browser_cls, - browser_kwargs, - executor_cls, - executor_kwargs, - kwargs["rerun"], - kwargs["pause_after_test"], - kwargs["pause_on_unexpected"], - kwargs["restart_on_unexpected"], - kwargs["debug_info"]) as manager_group: - try: - manager_group.run(test_type, run_tests) - except KeyboardInterrupt: - logger.critical("Main thread got signal") - manager_group.stop() - raise - test_count += manager_group.test_count() - unexpected_count += manager_group.unexpected_count() - - test_total += test_count - unexpected_total += unexpected_count - logger.info("Got %i unexpected results" % unexpected_count) - if repeat_until_unexpected and unexpected_total > 0: - break - logger.suite_end() + with wptlogging.LoggingQueue(logger) as logging_queue: + with wptlogging.CaptureIO(logging_queue, not kwargs["no_capture_stdio"]): + env.do_delayed_imports(logger, test_paths) + + (check_args, + target_browser_cls, get_browser_kwargs, + executor_classes, get_executor_kwargs, + env_options, get_env_extras, run_info_extras) = products.load_product(config, product) + + ssl_env = env.ssl_env(logger, **kwargs) + env_extras = get_env_extras(**kwargs) + + check_args(**kwargs) + + if kwargs["install_fonts"]: + env_extras.append(FontInstaller( + font_dir=kwargs["font_dir"], + ahem=os.path.join(kwargs["tests_root"], "fonts/Ahem.ttf") + )) + + if "test_loader" in kwargs: + run_info = wpttest.get_run_info(kwargs["run_info"], product, + browser_version=kwargs.get("browser_version"), + debug=None, + extras=run_info_extras(**kwargs)) + test_loader = kwargs["test_loader"] + else: + run_info, test_loader = get_loader(test_paths, + product, + ssl_env, + run_info_extras=run_info_extras(**kwargs), + **kwargs) + + test_source_kwargs = {"processes": kwargs["processes"]} + if kwargs["run_by_dir"] is False: + test_source_cls = testloader.SingleTestSource + else: + # A value of None indicates infinite depth + test_source_cls = testloader.PathGroupedSource + test_source_kwargs["depth"] = kwargs["run_by_dir"] + + logger.info("Using %i client processes" % kwargs["processes"]) + + test_total = 0 + unexpected_total = 0 + + kwargs["pause_after_test"] = get_pause_after_test(test_loader, **kwargs) + + with env.TestEnvironment(logging_queue, + test_paths, + ssl_env, + kwargs["pause_after_test"], + kwargs["debug_info"], + env_options, + env_extras) as test_environment: + try: + test_environment.ensure_started() + except env.TestEnvironmentError as e: + logger.critical("Error starting test environment: %s" % e.message) + raise + + repeat = kwargs["repeat"] + repeat_count = 0 + repeat_until_unexpected = kwargs["repeat_until_unexpected"] + + while repeat_count < repeat or repeat_until_unexpected: + repeat_count += 1 + if repeat_until_unexpected: + logger.info("Repetition %i" % (repeat_count)) + elif repeat > 1: + logger.info("Repetition %i / %i" % (repeat_count, repeat)) + + test_count = 0 + unexpected_count = 0 + logger.suite_start(test_loader.test_ids, name='web-platform-test', run_info=run_info) + for test_type in kwargs["test_types"]: + logger.info("Running %s tests" % test_type) + + # WebDriver tests may create and destroy multiple browser + # processes as part of their expected behavior. These + # processes are managed by a WebDriver server binary. This + # obviates the need for wptrunner to provide a browser, so + # the NullBrowser is used in place of the "target" browser + if test_type == "wdspec": + browser_cls = NullBrowser + else: + browser_cls = target_browser_cls + + browser_kwargs = get_browser_kwargs(test_type, + run_info, + ssl_env=ssl_env, + config=test_environment.config, + **kwargs) + + executor_cls = executor_classes.get(test_type) + executor_kwargs = get_executor_kwargs(test_type, + test_environment.config, + test_environment.cache_manager, + run_info, + **kwargs) + + if executor_cls is None: + logger.error("Unsupported test type %s for product %s" % + (test_type, product)) + continue + + for test in test_loader.disabled_tests[test_type]: + logger.test_start(test.id) + logger.test_end(test.id, status="SKIP") + + if test_type == "testharness": + run_tests = {"testharness": []} + for test in test_loader.tests["testharness"]: + if test.testdriver and not executor_cls.supports_testdriver: + logger.test_start(test.id) + logger.test_end(test.id, status="SKIP") + elif test.jsshell and not executor_cls.supports_jsshell: + # We expect that tests for JavaScript shells + # will not be run along with tests that run in + # a full web browser, so we silently skip them + # here. + pass + else: + run_tests["testharness"].append(test) + else: + run_tests = test_loader.tests + + with ManagerGroup("web-platform-tests", + kwargs["processes"], + test_source_cls, + test_source_kwargs, + browser_cls, + browser_kwargs, + executor_cls, + executor_kwargs, + kwargs["rerun"], + kwargs["pause_after_test"], + kwargs["pause_on_unexpected"], + kwargs["restart_on_unexpected"], + kwargs["debug_info"]) as manager_group: + try: + manager_group.run(test_type, run_tests) + except KeyboardInterrupt: + logger.critical("Main thread got signal") + manager_group.stop() + raise + test_count += manager_group.test_count() + unexpected_count += manager_group.unexpected_count() + + test_total += test_count + unexpected_total += unexpected_count + logger.info("Got %i unexpected results" % unexpected_count) + if repeat_until_unexpected and unexpected_total > 0: + break + logger.suite_end() if test_total == 0: logger.error("No tests ran")