-
Notifications
You must be signed in to change notification settings - Fork 32
/
store-tests
executable file
·259 lines (213 loc) · 10.7 KB
/
store-tests
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
#!/usr/bin/env python3
# This file is part of Cockpit.
#
# Copyright (C) 2020 Red Hat, Inc.
#
# Cockpit is free software; you can redistribute it and/or modify it
# under the terms of the GNU Lesser General Public License as published by
# the Free Software Foundation; either version 2.1 of the License, or
# (at your option) any later version.
#
# Cockpit is distributed in the hope that it will be useful, but
# WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
# Lesser General Public License for more details.
#
# You should have received a copy of the GNU Lesser General Public License
# along with Cockpit; If not, see <http://www.gnu.org/licenses/>.
import argparse
import logging
import re
import sqlite3
import sys
import urllib.request
from datetime import datetime
from lib import testmap
from lib.network import host_ssl_context
from task import github
# Result line has form like:
# ok 2 test/verify/check-accounts TestAccounts.testExpire [ND@1]
# ok 103 test/verify/check-multi-machine TestMultiMachine.testTroubleshooting
# ok 289 test/verify/check-machines-lifecycle TestMachinesLifecycle.testDelete [ND@1] # SKIP Known issue #1543
# not ok 117 test/verify/check-metrics TestMetrics.testPcp
# not ok 305 test/verify/check-networking-bond TestBonding.testActive [ND@1]
# not ok 24 test/verify/check-foobar TestExample.testBasic [ND] # RETRY 2 (be robust against unstable tests)
re_run = re.compile(r"(not )?ok \d+ (\S+) (\S+)[^#]*(?:# RETRY \d+ \(([^)]+))?")
# duration appears in the line right above the ok/not okTAP result:
# 1 TEST PASSED [26s on centosci-tasks-6w5w6]
re_duration = re.compile(r"# \d TEST (FAILED|PASSED) \[(\d+)s")
DATE_FORMAT = "%Y-%m-%dT%H:%M:%S%z"
def main():
parser = argparse.ArgumentParser(description='Store information about failed tests')
parser.add_argument("--db", default="test-results.db", help="Database name")
parser.add_argument("--repo", help="Repository from which to process failures")
parser.add_argument("--verbose", action="store_true", help="Enable verbose logging")
parser.add_argument("--test-parser", metavar="LOGFILE",
help="Scan given log file for tests and print results; for testing the parser")
parser.add_argument("revision", help="SHA for which failures should be stored")
opts = parser.parse_args()
if opts.verbose:
logging.basicConfig(level=logging.DEBUG)
if opts.test_parser:
test_parser(opts.test_parser)
return
db_conn = sqlite3.connect(opts.db)
cursor = db_conn.cursor()
init_db(cursor)
api = github.GitHub(repo=opts.repo)
statuses = api.all_statuses(opts.revision)
if not statuses:
sys.exit(f"Revision {opts.revision} has no statuses")
contexts = {}
# Read the "status story"
# First we get 'Not yet tested' or 'Not yet tested (direct trigger)'
# Then when it is picked up we get "Testing in progress" and finally it is either red or green
# Putting it all together can give us data like number of retries, how long it waited to get
# testes, how long testing took...
# Create map from 'context' to array of 'testrun's where each is a map containing: (order in the
# array indicates retries, the first is original run, the second is the first retry...)
# 'repo', 'url', 'state', 'description'
# 'started' - when this run was picked by bot
# 'posted' - when this run was triggered
# 'finished' - when this run finished - 'state' is then either 'success', 'failure' or 'error'
for status in reversed(statuses):
if not testmap.is_valid_context(status["context"], api.repo):
continue
cc = contexts.setdefault(status["context"], [])
desc = status["description"]
if status["state"] == "pending":
if "progress" in desc:
cc[-1]["url"] = status["target_url"]
cc[-1]["started"] = datetime.strptime(status["created_at"], DATE_FORMAT).timestamp() # noqa:DTZ007
elif "Not yet tested" in desc:
new_run = {"posted": datetime.strptime(status["created_at"], DATE_FORMAT).timestamp()} # noqa:DTZ007
new_run["state"] = "pending"
cc.append(new_run)
else:
logging.warning("Pending status has unexpected description '%s', skipping.", desc)
elif status["state"] in ["success", "failure", "error"]:
cc[-1]["finished"] = datetime.strptime(status["created_at"], DATE_FORMAT).timestamp() # noqa:DTZ007
cc[-1]["state"] = status["state"]
if status["state"] == "error":
cc[-1]["description"] = desc
else:
logging.warning("Status has unexpected state '%s', skipping.", status["state"])
for context, statuses in contexts.items():
repo = api.repo
if "@" in context:
parts = context.split("@")
context = parts[0]
if not parts[1].startswith("bots"):
# Can contain branch (e.g `cockpit-project/cockpit/rhel-8`)
# if not given, defaults to primary branch
repo = parts[1]
for retry, status in enumerate(statuses):
posted = status["posted"] # This must be always present, lets fails if it isn't
url = status.get("url")
started = status.get("started", posted)
waited = started - posted
took = status.get("finished", started) - started
logging.debug(
"Processing %s%s as %s that waited %ss and took %ss in %s. %s",
context,
"(retry no." + str(retry) + ")" if retry else "",
status["state"] + (" (" + status["description"] + ")" if status.get("description") else ""),
waited, took, repo, url
)
# URL is our primary key, so if we don't have one, just fake something unique
if not url:
url = "-".join(["queued", opts.revision, context, str(retry)])
row = cursor.execute("SELECT id FROM TestRuns WHERE url = ?", (url, )).fetchone()
if row is not None:
logging.warning("Test run %s already exists as ID %i, skipping", url, row[0])
continue
run_id = insert_run(cursor, repo, opts.revision, context, url,
posted, retry, waited, took, status["state"],
status.get("description"))
if status.get("url"): # If we faked 'url' then don't try to scan it
raw_log = url[:-5] if url.endswith(".html") else url
logging.debug("scanning log %s", raw_log)
with urllib.request.urlopen(raw_log,
context=host_ssl_context(urllib.parse.urlparse(raw_log).netloc)) as fp:
data = fp.readlines()
for (testname, failed, retry_reason, seconds) in find_tests(data):
insert_test(cursor, run_id, testname, failed, retry_reason, seconds)
# Find coverage line - normally second to last line, so check only last 20 lines
for line in data[-20:]:
if b"Overall line coverage: " in line:
coverage_str = line.split(b"Overall line coverage: ")[1].strip()
coverage = float(coverage_str.strip(b"%"))
insert_coverage(cursor, run_id, coverage)
break
db_conn.commit()
db_conn.close()
def init_db(cursor):
cursor.execute("""CREATE TABLE if not exists TestRuns
(id INTEGER PRIMARY KEY,
project TEXT,
revision TEXT,
context TEXT,
url TEXT,
time TIMESTAMP,
retry INTEGER,
wait_seconds INTEGER,
run_seconds INTEGER,
state TEXT,
description TEXT,
UNIQUE (url))
""")
cursor.execute("""CREATE TABLE if not exists Tests
(testname TEXT NOT NULL,
retry_reason TEXT,
failed INTEGER,
run INTEGER NOT NULL,
seconds INTEGER NOT NULL,
FOREIGN KEY (run) REFERENCES TestRuns(id))
""")
cursor.execute("""CREATE TABLE if not exists TestCoverage
(coverage REAL,
run INTEGER NOT NULL,
FOREIGN KEY (run) REFERENCES TestRuns(id))
""")
def insert_run(cursor, project, revision, context, url, time, retry, waited, took, state, desc):
return cursor.execute("INSERT INTO TestRuns VALUES (null, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)",
(project, revision, context, url, time, retry, waited, took, state, desc)).lastrowid
def insert_test(cursor, run_id, testname, failed, retry_reason, seconds):
cursor.execute("INSERT INTO Tests VALUES (?, ?, ?, ?, ?)",
(testname, retry_reason, int(failed), run_id, int(seconds)))
def insert_coverage(cursor, run_id, coverage):
cursor.execute("INSERT INTO TestCoverage VALUES (?, ?)", (coverage, run_id))
def find_tests(fp):
last_msg = ""
prev_msg = ""
save_message = False
for line in fp:
line = line.decode('utf-8')
if save_message:
last_msg = line.strip()
save_message = False
continue
# If the issue is known, don't save unexpected messages
if line.startswith("ok ") and "SKIP Known issue" in line:
save_message = False
last_msg = ""
if "FAIL: Test completed, but found unexpected" in line and "raise" not in line:
save_message = True
m = re_run.match(line)
if m:
# sometimes line breaks are missing:
# not ok 117 test/verify/check-metrics TestMetrics.testPcp
testname = f"{m.group(2)} {m.group(3)}".rstrip("#")
if "make-checkout-workdir" in testname:
testname = testname.split("make-checkout-workdir")[1]
t = re_duration.match(prev_msg)
yield (testname, bool(m.group(1)), last_msg or (m.group(4) or None), (t and t.group(2)) or 0)
last_msg = ""
prev_msg = line.strip()
def test_parser(logfile):
with open(logfile, 'rb') as f:
for (testname, failed, retry_reason, seconds) in find_tests(f):
print(f"{'FAIL' if failed else 'PASS'} {testname} "
f"{('RETRY:' + retry_reason) if retry_reason else ''} time {seconds}s")
if __name__ == '__main__':
main()