1# 2# Copyright (C) 2024 The Android Open Source Project 3# 4# Licensed under the Apache License, Version 2.0 (the "License"); 5# you may not use this file except in compliance with the License. 6# You may obtain a copy of the License at 7# 8# http://www.apache.org/licenses/LICENSE-2.0 9# 10# Unless required by applicable law or agreed to in writing, software 11# distributed under the License is distributed on an "AS IS" BASIS, 12# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13# See the License for the specific language governing permissions and 14# limitations under the License. 15# 16"""Log processing utilities""" 17 18import errno 19import os 20import pty 21import re 22import time 23import shutil 24import threading 25 26class ModuleQueue: 27 """Class representing a queue of modules being built 28 29 There are 2 types of log messages coming from the 30 underlying build subprocess: 31 - 'start' message determining that some task for the module 32 is started 33 - 'done' message determining that some task for the module 34 is finished 35 36 Then 'start' message comes, the task is stored in ModuleStatus 37 pending tasks set of the corresponding module in 'active' map. 38 39 The module itself is also pushed to front in 'queued'. 40 41 Module's status message is updated to the new started task name. 42 43 Then 'done' message comes, it is looked up in corresponding module 44 pending tasks set and popped out. 45 46 If it was the last task of the module, its name is displayed 47 as a status message of the module with 'done' mark. Otherwise, 48 next pending task is displayed as a status message. 49 50 Some messages can be 'start' and 'done' at the same time 51 (e.g. checkpoint messages). They are popped out immediately, 52 but update the status message. 53 54 """ 55 56 class ModuleStatus: 57 """Class representing module build status 58 59 Used to store a set of pending tasks for each module 60 and displaying it as a pinned status lines in colored build 61 log. 62 63 message: the message displayed as module status 64 pending: map of pending (unfinished) tasks for the module, 65 if there are no pending tasks for a module, 66 it is treated as done 67 """ 68 def __init__(self): 69 self.message = "" 70 self.pending = {} 71 72 def done(self): 73 return not self.pending 74 75 def __init__(self): 76 self.queued = [] 77 self.active = {} 78 79 def len(self): 80 diagnostic = "lengths of queued and active should be always equal" 81 assert len(self.queued) == len(self.active), diagnostic 82 return len(self.queued) 83 84 def insert(self, key, val: tuple[str, bool]): 85 """Insert/update a task in module status""" 86 if key in self.active: 87 # remove elem from the queue to bring it to the top 88 self.queued.remove(key) 89 else: 90 # allocate new module status entry 91 self.active[key] = self.ModuleStatus() 92 self.queued.append(key) 93 94 message, done = val 95 active_entry = self.active[key] 96 97 if done: 98 done_time = 0 99 100 if not message: 101 # consider all pending tasks done 102 active_entry.pending.clear() 103 elif message in active_entry.pending: 104 # remove from pending 105 done_time = time.time() - active_entry.pending[message] 106 active_entry.pending.pop(message) 107 108 # update module status message 109 if active_entry.done(): 110 # show last done message if done 111 active_entry.message = message, done_time, done 112 else: 113 # show first pending message if any 114 message, start_time = list(active_entry.pending.items())[0] 115 active_entry.message = message, start_time, False 116 else: 117 start_time = time.time() 118 # add task to pending (record its start time) 119 active_entry.pending[message] = start_time 120 active_entry.message = message, start_time, done 121 122 def pop_front(self): 123 """Finds a done module to pop from the queue""" 124 # find first done entry 125 pop = None 126 for m in self.queued: 127 if self.active[m].done(): 128 pop = m 129 self.queued.remove(m) 130 break 131 132 if pop is None: 133 # pops nothing if all remaining modules 134 # are still building (have at least one pending task) 135 return None, None 136 137 ret = pop, self.active[pop].message 138 139 # remove also from the dict 140 self.active.pop(pop) 141 142 return ret 143 144class LogProcessor(threading.Thread): 145 """Thread for processing build output 146 147 log_*: markers inserted by build system that help 148 parsing the log, should be the same as defined in 149 extern/lk/make/macro.mk 150 pinned_num: number of pinned status lines in build output 151 stream: build output stream to process 152 err: Determines which build output stream is attached 153 True for stderr, False for stdout 154 pinned: set of ModuleStatus objects that are currently processed 155 lock: lock to dispatch output from 2 pipe threads (stdout/stderr) 156 colored: a flag for colored output 157 log_file: optional file handle to duplicate the output 158 ansi_escape: regular expression to apply on output before 159 putting it to the log file (removes clang/rustc colors) 160 161 """ 162 163 log_prefix = "@log@" 164 log_done = "@done@" 165 log_sdone = "@sdone@" 166 log_print = "@print@" 167 log_separator = "@:@" 168 169 pinned_num = 10 170 171 class color: 172 """ANSI escape codes for colored output""" 173 red = "\x1b[31;20m" 174 bold_red = "\x1b[31;1m" 175 green = "\x1b[32;20m" 176 bold_green = "\x1b[32;1m" 177 yellow = "\x1b[33;20m" 178 bold_yellow = "\x1b[33;1m" 179 magenta = "\x1b[35;20m" 180 bold_magenta = "\x1b[35;1m" 181 cyan = "\x1b[36;20m" 182 bold_cyan = "\x1b[36;1m" 183 white = "\x1b[37;20m" 184 bold_white = "\x1b[37;1m" 185 grey = "\x1b[38;20m" 186 bold = "\x1b[1m" 187 reset = "\x1b[0m" 188 189 def __init__(self, stream, err, pinned, lock, colored, log_file): 190 threading.Thread.__init__(self) 191 192 self.stream = stream 193 self.err = err 194 self.pinned = pinned 195 self.lock = lock 196 self.colored = colored 197 self.log_file = log_file 198 self.ansi_escape = re.compile(r'(\x9B|\x1B\[)[0-?]*[ -\/]*[@-~]') 199 200 self.daemon = False 201 202 def colorize(self, string, color): 203 """Adds color to a string""" 204 return color + string + self.color.reset if self.colored else string 205 206 def display(self, module_status, entry, pinned): 207 """Displays a message on terminal""" 208 module, status = module_status 209 message, start_time, done = entry 210 211 if pinned: 212 # know actual terminal size, so can adjust status line length 213 term_width, _ = shutil.get_terminal_size((80, 24)) 214 215 # make sure whole line fits into a limit (max_total_width) 216 max_module_width = term_width // 2 217 if len(module) > max_module_width: 218 module = "..." + module[-max_module_width + 3:] 219 220 mwidth = term_width - len(module) - len(status) - 5 - 10 221 if mwidth - 3 <= 0: 222 # too small terminal window? 223 message = "" 224 status = status[:mwidth] 225 elif len(message) > mwidth: 226 message = "..." + message[-mwidth + 3:] 227 228 # color the message 229 module = self.colorize(module, self.color.bold_green) 230 status = self.colorize(status, self.color.green) 231 if done: 232 message += " " + self.colorize( 233 f'{start_time:3.1f}s done', self.color.green) 234 else: 235 running_time = time.time() - start_time 236 message += ' ' + self.colorize( 237 f'{running_time:3.1f}s', self.color.yellow) 238 239 print(f'{module}: {status} {message}') 240 241 def erase_pinned(self): 242 """Erases pinned status lines from the terminal""" 243 # scroll back to the beginning of pinned messages 244 # so, next message will print over 245 nerase = self.pinned_num 246 print(f'\033[{nerase}A', end = '') 247 248 # erase pinned messages before printing new stuff over 249 print('\033[0J', end = '') 250 251 def print_pinned(self): 252 """Prints self.pinned_num pinned messages to the terminal""" 253 254 # drop some old entries if it is too long 255 while self.pinned.len() > self.pinned_num: 256 # pop old done entries from pinned list 257 module_status, _ = self.pinned.pop_front() 258 if module_status is None: 259 # no more entries to pop, leave it as is 260 break 261 262 i = 0 263 for mstatus in self.pinned.queued: 264 if i == self.pinned_num: 265 break 266 self.display(mstatus, self.pinned.active[mstatus].message, True) 267 i = i + 1 268 269 if i < self.pinned_num: 270 # padd with empty lines 271 for i in range(self.pinned_num - self.pinned.len()): 272 print("") 273 274 def process(self, long_line, error): 275 """Processes a log message from the build system""" 276 self.lock.acquire() 277 278 # look for a special marker in output 279 marker_index = long_line.find(self.log_prefix) 280 if marker_index != -1: 281 # sometimes multiple log lines are glued together 282 # for some reason, split it here 283 lines = long_line[marker_index:].split(self.log_prefix) 284 for line in lines: 285 if line[:len(self.log_print)] == self.log_print: 286 line = line[len(self.log_print):] 287 # print marker, print immediately 288 if self.log_file is not None: 289 self.log_file.write(line) 290 291 line = self.colorize(line, self.color.bold_cyan) 292 self.erase_pinned() 293 print(line, end = "") 294 self.print_pinned() 295 continue 296 297 line = line.strip() 298 299 if not line: 300 continue 301 302 # check if a done marker inserted 303 done = False 304 silent = False 305 if line[:len(self.log_done)] == self.log_done: 306 line = line[len(self.log_done):] 307 done = True 308 if line[:len(self.log_sdone)] == self.log_sdone: 309 line = line[len(self.log_sdone):] 310 done = True 311 silent = True 312 313 parsed = line.split(self.log_separator, 2) 314 315 if len(parsed) != 3: 316 # malformed message 317 continue 318 319 module, status, message = parsed 320 if not module: 321 # log stream corrupted? Assign to 'root' module 322 module = "root" 323 324 self.pinned.insert((module, status), (message, done)) 325 326 if self.log_file is not None: 327 # put all messages to the log file as they go 328 if not silent: 329 self.log_file.write(f'{module}: {status} {message}\n') 330 else: # no markers 331 line = long_line 332 if error: 333 # put additional colors on error stream messages 334 if self.ansi_escape.search(line) is not None: 335 # if output is from clang or rustc and has colors already, 336 # keep it as is 337 pass 338 elif (pos := line.lower().find('error')) != -1: 339 line = self.colorize(line[:pos], self.color.bold) + \ 340 self.colorize('error', self.color.bold_red) + \ 341 self.colorize(line[pos + len('error'):], 342 self.color.bold) 343 elif (pos := line.lower().find('warning')) != -1: 344 line = self.colorize(line[:pos], self.color.bold) + \ 345 self.colorize('warning', self.color.bold_magenta) + \ 346 self.colorize(line[pos + len('warning'):], 347 self.color.bold) 348 else: 349 line = self.colorize(line, self.color.bold) 350 351 self.erase_pinned() 352 print(line, end = "") 353 self.print_pinned() 354 355 if self.log_file is not None: 356 # just print the message as is 357 # make sure no escape (color) characters go to the log file 358 line = self.ansi_escape.sub('', line) 359 self.log_file.write(line) 360 361 self.lock.release() 362 363 def refresh(self): 364 """Reprints pinned messages""" 365 self.lock.acquire() 366 self.erase_pinned() 367 self.print_pinned() 368 self.lock.release() 369 370 def run(self): 371 try: 372 with open(self.stream, encoding="utf-8") as stream: 373 for line in stream: 374 if not line: 375 break 376 self.process(line, self.err) 377 except OSError as e: 378 if errno.EIO == e.errno: 379 # EIO also means EOF, maybe just the pipe is closed 380 # on the other side 381 pass 382 else: 383 raise 384 385class LogEngine(): 386 """Log processing engine""" 387 388 class RepeatTimer(threading.Timer): 389 """Thread for repeatedly refreshing pinned messages""" 390 def run(self): 391 while not self.finished.wait(self.interval): 392 self.function(*self.args, **self.kwargs) 393 394 def __init__(self, log_file, colored=True): 395 # a queue where all pinned log lines are stored 396 pinned = ModuleQueue() 397 398 # lock to sync output between threads (stdout and stderr) 399 lock = threading.Lock() 400 401 self.log_file = log_file 402 403 # create pty buffers to capture output from the subprocess 404 # this is necessary to keep clang and rustc colored output 405 master_err, self.stderr = pty.openpty() 406 master_out, self.stdout = pty.openpty() 407 408 self.outThread = LogProcessor(stream=master_out, err=False, 409 pinned=pinned, lock=lock, colored=colored, log_file=self.log_file) 410 self.errThread = LogProcessor(stream=master_err, err=True, 411 pinned=pinned, lock=lock, colored=colored, log_file=self.log_file) 412 413 self.refresher = self.RepeatTimer(0.1, self.outThread.refresh) 414 415 def __enter__(self): 416 # no pinned entries yet, but print it now to allocate space 417 self.outThread.print_pinned() 418 419 self.outThread.start() 420 self.errThread.start() 421 422 # launch a pinned messages refreshing task 423 self.refresher.start() 424 return self 425 426 def __exit__(self, exception_type, value, traceback): 427 # stop log processor and refresher threads 428 self.refresher.cancel() 429 430 # make sure the latest pinned messages are printed 431 self.outThread.refresh() 432 433 # close remaining pipe ports 434 os.close(self.stdout) 435 os.close(self.stderr) 436 437 self.outThread.join() 438 self.errThread.join() 439