Unreviewed. Update W3C WebDriver imported tests.
[WebKit-https.git] / WebDriverTests / imported / w3c / tools / wptrunner / wptrunner / stability.py
1 import copy
2 import functools
3 import imp
4 import os
5 import sys
6 from collections import OrderedDict, defaultdict
7 from datetime import datetime
8
9 from mozlog import reader
10 from mozlog.formatters import JSONFormatter, TbplFormatter
11 from mozlog.handlers import BaseHandler, LogLevelFilter, StreamHandler
12
13 here = os.path.dirname(__file__)
14 localpaths = imp.load_source("localpaths", os.path.abspath(os.path.join(here, os.pardir, os.pardir, "localpaths.py")))
15 from wpt.markdown import markdown_adjust, table
16
17
18 class LogActionFilter(BaseHandler):
19
20     """Handler that filters out messages not of a given set of actions.
21
22     Subclasses BaseHandler.
23
24     :param inner: Handler to use for messages that pass this filter
25     :param actions: List of actions for which to fire the handler
26     """
27
28     def __init__(self, inner, actions):
29         """Extend BaseHandler and set inner and actions props on self."""
30         BaseHandler.__init__(self, inner)
31         self.inner = inner
32         self.actions = actions
33
34     def __call__(self, item):
35         """Invoke handler if action is in list passed as constructor param."""
36         if item["action"] in self.actions:
37             return self.inner(item)
38
39
40 class LogHandler(reader.LogHandler):
41
42     """Handle updating test and subtest status in log.
43
44     Subclasses reader.LogHandler.
45     """
46     def __init__(self):
47         self.results = OrderedDict()
48
49     def find_or_create_test(self, data):
50         test_name = data["test"]
51         if self.results.get(test_name):
52             return self.results[test_name]
53
54         test = {
55             "subtests": OrderedDict(),
56             "status": defaultdict(int)
57         }
58         self.results[test_name] = test
59         return test
60
61     def find_or_create_subtest(self, data):
62         test = self.find_or_create_test(data)
63         subtest_name = data["subtest"]
64
65         if test["subtests"].get(subtest_name):
66             return test["subtests"][subtest_name]
67
68         subtest = {
69             "status": defaultdict(int),
70             "messages": set()
71         }
72         test["subtests"][subtest_name] = subtest
73
74         return subtest
75
76     def test_status(self, data):
77         subtest = self.find_or_create_subtest(data)
78         subtest["status"][data["status"]] += 1
79         if data.get("message"):
80             subtest["messages"].add(data["message"])
81
82     def test_end(self, data):
83         test = self.find_or_create_test(data)
84         test["status"][data["status"]] += 1
85
86
87 def is_inconsistent(results_dict, iterations):
88     """Return whether or not a single test is inconsistent."""
89     return len(results_dict) > 1 or sum(results_dict.values()) != iterations
90
91
92 def process_results(log, iterations):
93     """Process test log and return overall results and list of inconsistent tests."""
94     inconsistent = []
95     handler = LogHandler()
96     reader.handle_log(reader.read(log), handler)
97     results = handler.results
98     for test_name, test in results.iteritems():
99         if is_inconsistent(test["status"], iterations):
100             inconsistent.append((test_name, None, test["status"], []))
101         for subtest_name, subtest in test["subtests"].iteritems():
102             if is_inconsistent(subtest["status"], iterations):
103                 inconsistent.append((test_name, subtest_name, subtest["status"], subtest["messages"]))
104     return results, inconsistent
105
106
107 def err_string(results_dict, iterations):
108     """Create and return string with errors from test run."""
109     rv = []
110     total_results = sum(results_dict.values())
111     for key, value in sorted(results_dict.items()):
112         rv.append("%s%s" %
113                   (key, ": %s/%s" % (value, iterations) if value != iterations else ""))
114     if total_results < iterations:
115         rv.append("MISSING: %s/%s" % (iterations - total_results, iterations))
116     rv = ", ".join(rv)
117     if is_inconsistent(results_dict, iterations):
118         rv = "**%s**" % rv
119     return rv
120
121
122 def write_inconsistent(log, inconsistent, iterations):
123     """Output inconsistent tests to logger.error."""
124     log("## Unstable results ##\n")
125     strings = [(
126         "`%s`" % markdown_adjust(test),
127         ("`%s`" % markdown_adjust(subtest)) if subtest else "",
128         err_string(results, iterations),
129         ("`%s`" % markdown_adjust(";".join(messages))) if len(messages) else "")
130         for test, subtest, results, messages in inconsistent]
131     table(["Test", "Subtest", "Results", "Messages"], strings, log)
132
133
134 def write_results(log, results, iterations, pr_number=None, use_details=False):
135     log("## All results ##\n")
136     if use_details:
137         log("<details>\n")
138         log("<summary>%i %s ran</summary>\n\n" % (len(results),
139                                                   "tests" if len(results) > 1
140                                                   else "test"))
141
142     for test_name, test in results.iteritems():
143         baseurl = "http://w3c-test.org/submissions"
144         if "https" in os.path.splitext(test_name)[0].split(".")[1:]:
145             baseurl = "https://w3c-test.org/submissions"
146         title = test_name
147         if use_details:
148             log("<details>\n")
149             if pr_number:
150                 title = "<a href=\"%s/%s%s\">%s</a>" % (baseurl, pr_number, test_name, title)
151             log('<summary>%s</summary>\n\n' % title)
152         else:
153             log("### %s ###" % title)
154         strings = [("", err_string(test["status"], iterations), "")]
155
156         strings.extend(((
157             ("`%s`" % markdown_adjust(subtest_name)) if subtest else "",
158             err_string(subtest["status"], iterations),
159             ("`%s`" % markdown_adjust(';'.join(subtest["messages"]))) if len(subtest["messages"]) else "")
160             for subtest_name, subtest in test["subtests"].items()))
161         table(["Subtest", "Results", "Messages"], strings, log)
162         if use_details:
163             log("</details>\n")
164
165     if use_details:
166         log("</details>\n")
167
168
169 def run_step(logger, iterations, restart_after_iteration, kwargs_extras, **kwargs):
170     import wptrunner
171     kwargs = copy.deepcopy(kwargs)
172
173     if restart_after_iteration:
174         kwargs["repeat"] = iterations
175     else:
176         kwargs["rerun"] = iterations
177
178     kwargs["pause_after_test"] = False
179     kwargs.update(kwargs_extras)
180
181     handler = LogActionFilter(
182         LogLevelFilter(
183             StreamHandler(
184                 sys.stdout,
185                 TbplFormatter()
186             ),
187             "WARNING"),
188         ["log", "process_output"])
189
190     # There is a public API for this in the next mozlog
191     initial_handlers = logger._state.handlers
192     logger._state.handlers = []
193
194     with open("raw.log", "wb") as log:
195         # Setup logging for wptrunner that keeps process output and
196         # warning+ level logs only
197         logger.add_handler(handler)
198         logger.add_handler(StreamHandler(log, JSONFormatter()))
199
200         wptrunner.run_tests(**kwargs)
201
202     logger._state.handlers = initial_handlers
203
204     with open("raw.log", "rb") as log:
205         results, inconsistent = process_results(log, iterations)
206     return results, inconsistent, iterations
207
208
209 def get_steps(logger, repeat_loop, repeat_restart, kwargs_extras):
210     steps = []
211     for kwargs_extra in kwargs_extras:
212         if kwargs_extra:
213             flags_string = " with flags %s" % " ".join(
214                 "%s=%s" % item for item in kwargs_extra.iteritems())
215         else:
216             flags_string = ""
217
218         if repeat_loop:
219             desc = "Running tests in a loop %d times%s" % (repeat_loop,
220                                                            flags_string)
221             steps.append((desc, functools.partial(run_step, logger, repeat_loop, False, kwargs_extra)))
222
223         if repeat_restart:
224             desc = "Running tests in a loop with restarts %s times%s" % (repeat_restart,
225                                                                          flags_string)
226             steps.append((desc, functools.partial(run_step, logger, repeat_restart, True, kwargs_extra)))
227
228     return steps
229
230
231 def write_summary(logger, step_results, final_result):
232     for desc, result in step_results:
233         logger.info('::: %s : %s' % (desc, result))
234     logger.info(':::')
235     if final_result == "PASS":
236         log = logger.info
237     elif final_result == "TIMEOUT":
238         log = logger.warning
239     else:
240         log = logger.error
241     log('::: Test verification %s' % final_result)
242
243     logger.info(':::')
244
245
246 def check_stability(logger, repeat_loop=10, repeat_restart=5, chaos_mode=True, max_time=None,
247                     output_results=True, **kwargs):
248     kwargs_extras = [{}]
249     if chaos_mode and kwargs["product"] == "firefox":
250         kwargs_extras.append({"chaos_mode_flags": 3})
251
252     steps = get_steps(logger, repeat_loop, repeat_restart, kwargs_extras)
253
254     start_time = datetime.now()
255     step_results = []
256
257     for desc, step_func in steps:
258         if max_time and datetime.now() - start_time > max_time:
259             logger.info("::: Test verification is taking too long: Giving up!")
260             logger.info("::: So far, all checks passed, but not all checks were run.")
261             write_summary(logger, step_results, "TIMEOUT")
262             return 2
263
264         logger.info(':::')
265         logger.info('::: Running test verification step "%s"...' % desc)
266         logger.info(':::')
267         results, inconsistent, iterations = step_func(**kwargs)
268         if output_results:
269             write_results(logger.info, results, iterations)
270
271         if inconsistent:
272             step_results.append((desc, "FAIL"))
273             write_inconsistent(logger.info, inconsistent, iterations)
274             write_summary(logger, step_results, "FAIL")
275             return 1
276
277         step_results.append((desc,  "PASS"))
278
279     write_summary(logger, step_results, "PASS")