diff options
-rw-r--r-- | bitbake/lib/bb/ui/teamcity.py | 398 |
1 files changed, 398 insertions, 0 deletions
diff --git a/bitbake/lib/bb/ui/teamcity.py b/bitbake/lib/bb/ui/teamcity.py new file mode 100644 index 0000000000..1854292fa1 --- /dev/null +++ b/bitbake/lib/bb/ui/teamcity.py | |||
@@ -0,0 +1,398 @@ | |||
1 | # | ||
2 | # TeamCity UI Implementation | ||
3 | # | ||
4 | # Implements a TeamCity frontend for the BitBake utility, via service messages. | ||
5 | # See https://www.jetbrains.com/help/teamcity/build-script-interaction-with-teamcity.html | ||
6 | # | ||
7 | # Based on ncurses.py and knotty.py, variously by Michael Lauer and Richard Purdie | ||
8 | # | ||
9 | # Copyright (C) 2006 Michael 'Mickey' Lauer | ||
10 | # Copyright (C) 2006-2012 Richard Purdie | ||
11 | # Copyright (C) 2018-2020 Agilent Technologies, Inc. | ||
12 | # | ||
13 | # SPDX-License-Identifier: GPL-2.0-only | ||
14 | # | ||
15 | # Author: Chris Laplante <chris.laplante@agilent.com> | ||
16 | |||
17 | from __future__ import division | ||
18 | |||
19 | import datetime | ||
20 | import logging | ||
21 | import math | ||
22 | import os | ||
23 | import re | ||
24 | import sys | ||
25 | import xmlrpc.client | ||
26 | from collections import deque | ||
27 | |||
28 | import bb | ||
29 | import bb.build | ||
30 | import bb.command | ||
31 | import bb.cooker | ||
32 | import bb.event | ||
33 | import bb.exceptions | ||
34 | import bb.runqueue | ||
35 | from bb.ui import uihelper | ||
36 | |||
37 | logger = logging.getLogger("BitBake") | ||
38 | |||
39 | |||
40 | class TeamCityUI: | ||
41 | def __init__(self): | ||
42 | self._block_stack = [] | ||
43 | self._last_progress_state = None | ||
44 | |||
45 | @classmethod | ||
46 | def escape_service_value(cls, value): | ||
47 | """ | ||
48 | Escape a value for inclusion in a service message. TeamCity uses the vertical pipe character for escaping. | ||
49 | See: https://confluence.jetbrains.com/display/TCD10/Build+Script+Interaction+with+TeamCity#BuildScriptInteractionwithTeamCity-Escapedvalues | ||
50 | """ | ||
51 | return re.sub(r"(['|\[\]])", r"|\1", value).replace("\n", "|n").replace("\r", "|r") | ||
52 | |||
53 | @classmethod | ||
54 | def emit_service_message(cls, message_type, **kwargs): | ||
55 | print(cls.format_service_message(message_type, **kwargs), flush=True) | ||
56 | |||
57 | @classmethod | ||
58 | def format_service_message(cls, message_type, **kwargs): | ||
59 | payload = " ".join(["{0}='{1}'".format(k, cls.escape_service_value(v)) for k, v in kwargs.items()]) | ||
60 | return "##teamcity[{0} {1}]".format(message_type, payload) | ||
61 | |||
62 | @classmethod | ||
63 | def emit_simple_service_message(cls, message_type, message): | ||
64 | print(cls.format_simple_service_message(message_type, message), flush=True) | ||
65 | |||
66 | @classmethod | ||
67 | def format_simple_service_message(cls, message_type, message): | ||
68 | return "##teamcity[{0} '{1}']".format(message_type, cls.escape_service_value(message)) | ||
69 | |||
70 | @classmethod | ||
71 | def format_build_message(cls, text, status): | ||
72 | return cls.format_service_message("message", text=text, status=status) | ||
73 | |||
74 | def block_start(self, name): | ||
75 | self._block_stack.append(name) | ||
76 | self.emit_service_message("blockOpened", name=name) | ||
77 | |||
78 | def block_end(self): | ||
79 | if self._block_stack: | ||
80 | name = self._block_stack.pop() | ||
81 | self.emit_service_message("blockClosed", name=name) | ||
82 | |||
83 | def progress(self, message, percent, extra=None): | ||
84 | now = datetime.datetime.now() | ||
85 | percent = "{0: >3.0f}".format(percent) | ||
86 | |||
87 | report = False | ||
88 | if not self._last_progress_state \ | ||
89 | or (self._last_progress_state[0] == message | ||
90 | and self._last_progress_state[1] != percent | ||
91 | and (now - self._last_progress_state[2]).microseconds >= 5000) \ | ||
92 | or self._last_progress_state[0] != message: | ||
93 | report = True | ||
94 | self._last_progress_state = (message, percent, now) | ||
95 | |||
96 | if report or percent in [0, 100]: | ||
97 | self.emit_simple_service_message("progressMessage", "{0}: {1}%{2}".format(message, percent, extra or "")) | ||
98 | |||
99 | |||
100 | class TeamcityLogFormatter(logging.Formatter): | ||
101 | def format(self, record): | ||
102 | details = "" | ||
103 | if hasattr(record, 'bb_exc_formatted'): | ||
104 | details = ''.join(record.bb_exc_formatted) | ||
105 | elif hasattr(record, 'bb_exc_info'): | ||
106 | etype, value, tb = record.bb_exc_info | ||
107 | formatted = bb.exceptions.format_exception(etype, value, tb, limit=5) | ||
108 | details = ''.join(formatted) | ||
109 | |||
110 | if record.levelno in [bb.msg.BBLogFormatter.ERROR, bb.msg.BBLogFormatter.CRITICAL]: | ||
111 | # ERROR gets a separate errorDetails field | ||
112 | msg = TeamCityUI.format_service_message("message", text=record.getMessage(), status="ERROR", | ||
113 | errorDetails=details) | ||
114 | else: | ||
115 | payload = record.getMessage() | ||
116 | if details: | ||
117 | payload += "\n" + details | ||
118 | if record.levelno == bb.msg.BBLogFormatter.PLAIN: | ||
119 | msg = payload | ||
120 | elif record.levelno == bb.msg.BBLogFormatter.WARNING: | ||
121 | msg = TeamCityUI.format_service_message("message", text=payload, status="WARNING") | ||
122 | else: | ||
123 | msg = TeamCityUI.format_service_message("message", text=payload, status="NORMAL") | ||
124 | |||
125 | return msg | ||
126 | |||
127 | |||
128 | _evt_list = ["bb.runqueue.runQueueExitWait", "bb.event.LogExecTTY", "logging.LogRecord", | ||
129 | "bb.build.TaskFailed", "bb.build.TaskBase", "bb.event.ParseStarted", | ||
130 | "bb.event.ParseProgress", "bb.event.ParseCompleted", "bb.event.CacheLoadStarted", | ||
131 | "bb.event.CacheLoadProgress", "bb.event.CacheLoadCompleted", "bb.command.CommandFailed", | ||
132 | "bb.command.CommandExit", "bb.command.CommandCompleted", "bb.cooker.CookerExit", | ||
133 | "bb.event.MultipleProviders", "bb.event.NoProvider", "bb.runqueue.sceneQueueTaskStarted", | ||
134 | "bb.runqueue.runQueueTaskStarted", "bb.runqueue.runQueueTaskFailed", "bb.runqueue.sceneQueueTaskFailed", | ||
135 | "bb.event.BuildBase", "bb.build.TaskStarted", "bb.build.TaskSucceeded", "bb.build.TaskFailedSilent", | ||
136 | "bb.build.TaskProgress", "bb.event.ProcessStarted", "bb.event.ProcessProgress", "bb.event.ProcessFinished"] | ||
137 | |||
138 | |||
139 | def _log_settings_from_server(server): | ||
140 | # Get values of variables which control our output | ||
141 | includelogs, error = server.runCommand(["getVariable", "BBINCLUDELOGS"]) | ||
142 | if error: | ||
143 | logger.error("Unable to get the value of BBINCLUDELOGS variable: %s" % error) | ||
144 | raise BaseException(error) | ||
145 | loglines, error = server.runCommand(["getVariable", "BBINCLUDELOGS_LINES"]) | ||
146 | if error: | ||
147 | logger.error("Unable to get the value of BBINCLUDELOGS_LINES variable: %s" % error) | ||
148 | raise BaseException(error) | ||
149 | return includelogs, loglines | ||
150 | |||
151 | |||
152 | def main(server, eventHandler, params): | ||
153 | params.updateToServer(server, os.environ.copy()) | ||
154 | |||
155 | includelogs, loglines = _log_settings_from_server(server) | ||
156 | |||
157 | ui = TeamCityUI() | ||
158 | |||
159 | helper = uihelper.BBUIHelper() | ||
160 | |||
161 | console = logging.StreamHandler(sys.stdout) | ||
162 | errconsole = logging.StreamHandler(sys.stderr) | ||
163 | format = TeamcityLogFormatter() | ||
164 | if params.options.quiet == 0: | ||
165 | forcelevel = None | ||
166 | elif params.options.quiet > 2: | ||
167 | forcelevel = bb.msg.BBLogFormatter.ERROR | ||
168 | else: | ||
169 | forcelevel = bb.msg.BBLogFormatter.WARNING | ||
170 | bb.msg.addDefaultlogFilter(console, bb.msg.BBLogFilterStdOut, forcelevel) | ||
171 | bb.msg.addDefaultlogFilter(errconsole, bb.msg.BBLogFilterStdErr) | ||
172 | console.setFormatter(format) | ||
173 | errconsole.setFormatter(format) | ||
174 | if not bb.msg.has_console_handler(logger): | ||
175 | logger.addHandler(console) | ||
176 | logger.addHandler(errconsole) | ||
177 | |||
178 | if params.options.remote_server and params.options.kill_server: | ||
179 | server.terminateServer() | ||
180 | return | ||
181 | |||
182 | if params.observe_only: | ||
183 | logger.error("Observe-only mode not supported in this UI") | ||
184 | return 1 | ||
185 | |||
186 | llevel, debug_domains = bb.msg.constructLogOptions() | ||
187 | server.runCommand(["setEventMask", server.getEventHandle(), llevel, debug_domains, _evt_list]) | ||
188 | |||
189 | try: | ||
190 | params.updateFromServer(server) | ||
191 | cmdline = params.parseActions() | ||
192 | if not cmdline: | ||
193 | logger.error("No task given") | ||
194 | return 1 | ||
195 | if 'msg' in cmdline and cmdline['msg']: | ||
196 | logger.error(cmdline['msg']) | ||
197 | return 1 | ||
198 | cmdline = cmdline['action'] | ||
199 | ret, error = server.runCommand(cmdline) | ||
200 | if error: | ||
201 | logger.error("{0}: {1}".format(cmdline, error)) | ||
202 | return 1 | ||
203 | elif not ret: | ||
204 | logger.error("Couldn't get default commandline: {0}".format(re)) | ||
205 | return 1 | ||
206 | except xmlrpc.client.Fault as x: | ||
207 | logger.error("XMLRPC Fault getting commandline: {0}".format(x)) | ||
208 | return 1 | ||
209 | |||
210 | active_process_total = None | ||
211 | is_tasks_running = False | ||
212 | |||
213 | while True: | ||
214 | try: | ||
215 | event = eventHandler.waitEvent(0.25) | ||
216 | if not event: | ||
217 | continue | ||
218 | |||
219 | helper.eventHandler(event) | ||
220 | |||
221 | if isinstance(event, bb.build.TaskBase): | ||
222 | logger.info(event._message) | ||
223 | if isinstance(event, logging.LogRecord): | ||
224 | # Don't report sstate failures as errors, since Yocto will just run the tasks for real | ||
225 | if event.msg == "No suitable staging package found" or (event.msg.startswith( | ||
226 | "Fetcher failure: Unable to find file") and "downloadfilename" in event.msg and "sstate" in event.msg): | ||
227 | event.levelno = bb.msg.BBLogFormatter.WARNING | ||
228 | if event.taskpid != 0: | ||
229 | # For "normal" logging conditions, don't show note logs from tasks | ||
230 | # but do show them if the user has changed the default log level to | ||
231 | # include verbose/debug messages | ||
232 | if event.levelno <= bb.msg.BBLogFormatter.NOTE and (event.levelno < llevel or ( | ||
233 | event.levelno == bb.msg.BBLogFormatter.NOTE and llevel != bb.msg.BBLogFormatter.VERBOSE)): | ||
234 | continue | ||
235 | |||
236 | # Prefix task messages with recipe/task | ||
237 | if event.taskpid in helper.running_tasks and event.levelno != bb.msg.BBLogFormatter.PLAIN: | ||
238 | taskinfo = helper.running_tasks[event.taskpid] | ||
239 | event.msg = taskinfo['title'] + ': ' + event.msg | ||
240 | if hasattr(event, 'fn'): | ||
241 | event.msg = event.fn + ': ' + event.msg | ||
242 | logger.handle(event) | ||
243 | if isinstance(event, bb.build.TaskFailedSilent): | ||
244 | logger.warning("Logfile for failed setscene task is %s" % event.logfile) | ||
245 | continue | ||
246 | if isinstance(event, bb.build.TaskFailed): | ||
247 | rt = "{0}-{1}:{2}".format(event.pn, event.pv.replace("AUTOINC", "0"), event.task) | ||
248 | |||
249 | logfile = event.logfile | ||
250 | if not logfile or not os.path.exists(logfile): | ||
251 | TeamCityUI.emit_service_message("buildProblem", description="{0}\nUnknown failure (no log file available)".format(rt)) | ||
252 | if not event.task.endswith("_setscene"): | ||
253 | server.runCommand(["stateForceShutdown"]) | ||
254 | continue | ||
255 | |||
256 | details = deque(maxlen=loglines) | ||
257 | error_lines = [] | ||
258 | if includelogs and not event.errprinted: | ||
259 | with open(logfile, "r") as f: | ||
260 | while True: | ||
261 | line = f.readline() | ||
262 | if not line: | ||
263 | break | ||
264 | line = line.rstrip() | ||
265 | details.append(' | %s' % line) | ||
266 | # TODO: a less stupid check for errors | ||
267 | if (event.task == "do_compile") and ("error:" in line): | ||
268 | error_lines.append(line) | ||
269 | |||
270 | if error_lines: | ||
271 | TeamCityUI.emit_service_message("compilationStarted", compiler=rt) | ||
272 | for line in error_lines: | ||
273 | TeamCityUI.emit_service_message("message", text=line, status="ERROR") | ||
274 | TeamCityUI.emit_service_message("compilationFinished", compiler=rt) | ||
275 | else: | ||
276 | TeamCityUI.emit_service_message("buildProblem", description=rt) | ||
277 | |||
278 | err = "Logfile of failure stored in: %s" % logfile | ||
279 | if details: | ||
280 | ui.block_start("{0} task log".format(rt)) | ||
281 | # TeamCity seems to choke on service messages longer than about 63800 characters, so if error | ||
282 | # details is longer than, say, 60000, batch it up into several messages. | ||
283 | first_message = True | ||
284 | while details: | ||
285 | detail_len = 0 | ||
286 | batch = deque() | ||
287 | while details and detail_len < 60000: | ||
288 | # TODO: This code doesn't bother to handle lines that themselves are extremely long. | ||
289 | line = details.popleft() | ||
290 | batch.append(line) | ||
291 | detail_len += len(line) | ||
292 | |||
293 | if first_message: | ||
294 | batch.appendleft("Log data follows:") | ||
295 | first_message = False | ||
296 | TeamCityUI.emit_service_message("message", text=err, status="ERROR", | ||
297 | errorDetails="\n".join(batch)) | ||
298 | else: | ||
299 | TeamCityUI.emit_service_message("message", text="[continued]", status="ERROR", | ||
300 | errorDetails="\n".join(batch)) | ||
301 | ui.block_end() | ||
302 | else: | ||
303 | TeamCityUI.emit_service_message("message", text=err, status="ERROR", errorDetails="") | ||
304 | |||
305 | if not event.task.endswith("_setscene"): | ||
306 | server.runCommand(["stateForceShutdown"]) | ||
307 | |||
308 | if isinstance(event, bb.event.ProcessStarted): | ||
309 | if event.processname in ["Initialising tasks", "Checking sstate mirror object availability"]: | ||
310 | active_process_total = event.total | ||
311 | ui.block_start(event.processname) | ||
312 | if isinstance(event, bb.event.ProcessFinished): | ||
313 | if event.processname in ["Initialising tasks", "Checking sstate mirror object availability"]: | ||
314 | ui.progress(event.processname, 100) | ||
315 | ui.block_end() | ||
316 | if isinstance(event, bb.event.ProcessProgress): | ||
317 | if event.processname in ["Initialising tasks", | ||
318 | "Checking sstate mirror object availability"] and active_process_total != 0: | ||
319 | ui.progress(event.processname, event.progress * 100 / active_process_total) | ||
320 | if isinstance(event, bb.event.CacheLoadStarted): | ||
321 | ui.block_start("Loading cache") | ||
322 | if isinstance(event, bb.event.CacheLoadProgress): | ||
323 | if event.total != 0: | ||
324 | ui.progress("Loading cache", math.floor(event.current * 100 / event.total)) | ||
325 | if isinstance(event, bb.event.CacheLoadCompleted): | ||
326 | ui.progress("Loading cache", 100) | ||
327 | ui.block_end() | ||
328 | if isinstance(event, bb.event.ParseStarted): | ||
329 | ui.block_start("Parsing recipes and checking upstream revisions") | ||
330 | if isinstance(event, bb.event.ParseProgress): | ||
331 | if event.total != 0: | ||
332 | ui.progress("Parsing recipes", math.floor(event.current * 100 / event.total)) | ||
333 | if isinstance(event, bb.event.ParseCompleted): | ||
334 | ui.progress("Parsing recipes", 100) | ||
335 | ui.block_end() | ||
336 | if isinstance(event, bb.command.CommandCompleted): | ||
337 | return | ||
338 | if isinstance(event, bb.command.CommandFailed): | ||
339 | logger.error(str(event)) | ||
340 | return 1 | ||
341 | if isinstance(event, bb.event.MultipleProviders): | ||
342 | logger.warning(str(event)) | ||
343 | continue | ||
344 | if isinstance(event, bb.event.NoProvider): | ||
345 | logger.error(str(event)) | ||
346 | continue | ||
347 | if isinstance(event, bb.command.CommandExit): | ||
348 | return | ||
349 | if isinstance(event, bb.cooker.CookerExit): | ||
350 | return | ||
351 | if isinstance(event, bb.runqueue.sceneQueueTaskStarted): | ||
352 | if not is_tasks_running: | ||
353 | is_tasks_running = True | ||
354 | ui.block_start("Running tasks") | ||
355 | if event.stats.total != 0: | ||
356 | ui.progress("Running setscene tasks", ( | ||
357 | event.stats.completed + event.stats.active + event.stats.failed + 1) * 100 / event.stats.total) | ||
358 | if isinstance(event, bb.runqueue.runQueueTaskStarted): | ||
359 | if not is_tasks_running: | ||
360 | is_tasks_running = True | ||
361 | ui.block_start("Running tasks") | ||
362 | if event.stats.total != 0: | ||
363 | pseudo_total = event.stats.total - event.stats.skipped | ||
364 | pseudo_complete = event.stats.completed + event.stats.active - event.stats.skipped + event.stats.failed + 1 | ||
365 | # TODO: sometimes this gives over 100% | ||
366 | ui.progress("Running runqueue tasks", (pseudo_complete) * 100 / pseudo_total, | ||
367 | " ({0}/{1})".format(pseudo_complete, pseudo_total)) | ||
368 | if isinstance(event, bb.runqueue.sceneQueueTaskFailed): | ||
369 | logger.warning(str(event)) | ||
370 | continue | ||
371 | if isinstance(event, bb.runqueue.runQueueTaskFailed): | ||
372 | logger.error(str(event)) | ||
373 | return 1 | ||
374 | if isinstance(event, bb.event.LogExecTTY): | ||
375 | pass | ||
376 | except EnvironmentError as ioerror: | ||
377 | # ignore interrupted io | ||
378 | if ioerror.args[0] == 4: | ||
379 | pass | ||
380 | except Exception as ex: | ||
381 | logger.error(str(ex)) | ||
382 | |||
383 | # except KeyboardInterrupt: | ||
384 | # if shutdown == 2: | ||
385 | # mw.appendText("Third Keyboard Interrupt, exit.\n") | ||
386 | # exitflag = True | ||
387 | # if shutdown == 1: | ||
388 | # mw.appendText("Second Keyboard Interrupt, stopping...\n") | ||
389 | # _, error = server.runCommand(["stateForceShutdown"]) | ||
390 | # if error: | ||
391 | # print("Unable to cleanly stop: %s" % error) | ||
392 | # if shutdown == 0: | ||
393 | # mw.appendText("Keyboard Interrupt, closing down...\n") | ||
394 | # _, error = server.runCommand(["stateShutdown"]) | ||
395 | # if error: | ||
396 | # print("Unable to cleanly shutdown: %s" % error) | ||
397 | # shutdown = shutdown + 1 | ||
398 | # pass | ||