''' Support for multi-process safe logging with colorized output. ''' import os import sys import traceback import multiprocessing import enum import datetime #Use standard Semmle logging levels OFF = 0 ERROR = 1 WARN = 2 INFO = 3 DEBUG = 4 TRACE = 5 TRACEBACK = 6 COLOR = 8 if os.name == "nt": MAGENTA = "" GREY = "" BLUE = "" YELLOW = "" RED = "" RESET = "" else: MAGENTA = "\x1b[35m" GREY = "\x1b[2m\x1b[37m" BLUE = "\x1b[34m" YELLOW = "\x1b[33m" RED = "\x1b[31m" RESET = '\x1b[0m' LOG_PREFIX = { TRACE: "[TRACE] ", DEBUG: "[DEBUG] ", INFO: "[INFO] ", WARN: "[WARN] ", ERROR: "[ERROR] ", TRACEBACK: "[TRACEBACK] ", COLOR | TRACE: GREY + "[TRACE] ", COLOR | DEBUG: "[DEBUG] ", COLOR | INFO: BLUE + "[INFO] ", COLOR | WARN: YELLOW + "[WARN] ", COLOR | ERROR: RED + "[ERROR] ", COLOR | TRACEBACK: MAGENTA + "[TRACEBACK] ", } def write_message(level, text): '''Write a message direct to stdout without queueing.''' reset = RESET if level & COLOR == COLOR else '' print(LOG_PREFIX[level] + text + reset) sys.stdout.flush() def write_message_with_proc(level, proc_id, text): reset = RESET if level & COLOR == COLOR else '' print(LOG_PREFIX[level] + proc_id + text + reset) sys.stdout.flush() _logging_process = None def stop(): _logging_process.join() class Logger(object): '''Multi-process safe logger''' def __init__(self, level=WARN, color=False): global _logging_process self.proc_id = "" self.level = level # macOS does not support `fork` properly, so we must use `spawn` instead. method = 'spawn' if sys.platform == "darwin" else None try: ctx = multiprocessing.get_context(method) except AttributeError: # `get_context` doesn't exist -- we must be running an old version of Python. ctx = multiprocessing self.queue = ctx.Queue() _logging_process = ctx.Process(target=_message_loop, args=(self.queue,)) _logging_process.start() self.color = COLOR if color else 0 def __enter__(self): return self def __exit__(self, exc_type, exc_val, exc_tb): self.close() return False def set_process_id(self, proc_id): '''Set the process id to be included in log messages.''' self.proc_id = "[%d] " % proc_id def setLevel(self, level): self.level = level def log(self, level, fmt, *args): '''Log a message in a process safe fashion. Message will be of the form [level] fmt%args.''' if level <= self.level: txt = fmt % args try: self.queue.put((self.color | level, self.proc_id, txt), False) except Exception: self.write_message(self.color | level, txt) def debug(self, fmt, *args): self.log(DEBUG, fmt, *args) def info(self, fmt, *args): self.log(INFO, fmt, *args) def warning(self, fmt, *args): self.log(WARN, fmt, *args) def error(self, fmt, *args): self.log(ERROR, fmt, *args) def trace(self, fmt, *args): self.log(TRACE, fmt, *args) def traceback(self, level=INFO): if level > self.level: return lines = trim_traceback(traceback.format_exc()) for line in lines: try: self.queue.put((self.color | TRACEBACK, self.proc_id, line), False) except Exception: self.write_message(TRACEBACK, line) def close(self): self.queue.put(None) def write_message(self, level, text): '''Write a message direct to stdout without queueing. Safe to use even after logger is closed. Calling this concurrently from different processes or before calling logger.close() may cause messages to become interleaved.''' if level <= self.level: write_message_with_proc(self.color | level, self.proc_id, text) #Function run by logger output process def _message_loop(log_queue): # use utf-8 as the character encoding for stdout/stderr to be able to properly # log/print things on systems that use bad default encodings (windows). sys.stdout.reconfigure(encoding='utf-8') sys.stderr.reconfigure(encoding='utf-8') common = set() while True: try: msg = log_queue.get() if msg is None: return level, proc_id, text = msg if proc_id: write_message_with_proc(level, proc_id, text) elif (level, text) not in common: write_message(level, text) common.add((level, text)) except KeyboardInterrupt: #Will be handled in other processes. pass def select_traceback_lines(lines, limit_start=30, limit_end=12): '''Select a subset of traceback lines to be displayed, cutting out the middle part of the traceback if the length exceeds `limit_start + limit_end`. This is intended to avoid displaying too many lines of tracebacks that are not relevant to the user.''' lines = lines.splitlines() num_lines = len(lines) limit = limit_start + limit_end if num_lines <= limit: yield from lines else: yield from lines[:limit_start] yield "... {} lines skipped".format(num_lines - limit) yield from lines[-limit_end:] def trim_traceback(lines): trimmed = [] for line in select_traceback_lines(lines): shortline = line.strip() try: if shortline.startswith("File"): shortline = '"semmle' + shortline.split("semmle")[-1] elif shortline.startswith("..."): pass else: continue except Exception: #Formatting error, just emit line as-is. pass trimmed.append(shortline) return trimmed class StructuredLogObject(object): """ Base class for CodeQL diagnostic message format see https://github.com/github/code-scanning/blob/main/docs/adrs/0035-diagnostics.md#codeql-diagnostic-message-format """ def to_dict(self): # Discard any entries with a value of `None` def f(v): if isinstance(v, StructuredLogObject): return v.to_dict() return v return {k: f(v) for k, v in self.__dict__.items() if v is not None} class Severity(StructuredLogObject, enum.Enum): ERROR = "error" WARNING = "warning" NOTE = "note" def to_dict(self): return self.value class Source(StructuredLogObject): def __init__(self, id, name, extractorName="python"): self.id = id self.name = name self.extractorName = extractorName def extractorName(self, extractorName): self.extractorName = extractorName return self class Visibility(StructuredLogObject): def __init__(self, statusPage=False, cliSummaryTable=False, telemetry=False): self.statusPage = statusPage self.cliSummaryTable = cliSummaryTable self.telemetry = telemetry def statusPage(self, statusPage): self.statusPage = statusPage return self def cliSummaryTable(self, cliSummaryTable): self.cliSummaryTable = cliSummaryTable return self def telemetry(self, telemetry): self.telemetry = telemetry return self class Location(StructuredLogObject): def __init__(self, file=None, startLine=None, startColumn=None, endLine=None, endColumn=None): self.file = file self.startLine = startLine self.startColumn = startColumn # If you set startline/startColumn you MUST also set endLine/endColumn, so we # ensure they are also set. self.endLine = endLine if endLine is None and startLine is not None: self.endLine = startLine self.endColumn = endColumn if endColumn is None and startColumn is not None: self.endColumn = startColumn def file(self, file): self.file = file return self def startLine(self, startLine): self.startLine = startLine return self def startColumn(self, startColumn): self.startColumn = startColumn return self def endLine(self, endLine): self.endLine = endLine return self def endColumn(self, endColumn): self.endColumn = endColumn return self class DiagnosticMessage(StructuredLogObject): def __init__(self, source, severity=Severity.WARNING, location=None, markdownMessage=None, plaintextMessage=None, helpLinks=None, visibility=None, attributes=None, timestamp=None): self.timestamp = timestamp or datetime.datetime.now().isoformat() self.source = source self.severity = severity self.location = location self.markdownMessage = markdownMessage self.plaintextMessage = plaintextMessage self.helpLinks = helpLinks if visibility is None: visibility = Visibility() self.visibility = visibility self.attributes = attributes def with_severity(self, severity): self.severity = severity return self def with_location(self, location): self.location = location return self def markdown(self, message): self.markdownMessage = message return self def text(self, message): self.plaintextMessage = message return self def help_link(self, link): if self.helpLinks is None: self.helpLinks = [] self.helpLinks.append(link) return self def cli_summary_table(self): self.visibility.cliSummaryTable = True return self def status_page(self): self.visibility.statusPage = True return self def telemetry(self): self.visibility.telemetry = True return self def attribute(self, key, value): if self.attributes is None: self.attributes = {} self.attributes[key] = value return self def with_timestamp(self, timestamp): self.timestamp = timestamp return self def get_stack_trace_lines(): """Creates a stack trace for inclusion into the `attributes` part of a diagnostic message. Limits the size of the stack trace to 5000 characters, so as to not make the SARIF file overly big. """ lines = trim_traceback(traceback.format_exc()) trace_length = 0 for i, line in enumerate(lines): trace_length += len(line) if trace_length > 5000: return lines[:i] return lines def syntax_error_message(exception, unit): l = Location(file=unit.path, startLine=exception.lineno, startColumn=exception.offset) error = (DiagnosticMessage(Source("py/diagnostics/syntax-error", "Could not process some files due to syntax errors"), Severity.WARNING) .with_location(l) .markdown("A parse error occurred while processing `{}`, and as a result this file could not be analyzed. Check the syntax of the file using the `python -m py_compile` command and correct any invalid syntax.".format(unit.path)) .attribute("traceback", get_stack_trace_lines()) .attribute("args", exception.args) .status_page() .cli_summary_table() .telemetry() ) return error def recursion_error_message(exception, unit): # if unit is a BuiltinModuleExtractable, there will be no path attribute l = Location(file=unit.path) if hasattr(unit, "path") else None return (DiagnosticMessage(Source("py/diagnostics/recursion-error", "Recursion error in Python extractor"), Severity.ERROR) .with_location(l) .text(exception.args[0]) .attribute("traceback", get_stack_trace_lines()) .attribute("args", exception.args) .telemetry() ) def internal_error_message(exception, unit): # if unit is a BuiltinModuleExtractable, there will be no path attribute l = Location(file=unit.path) if hasattr(unit, "path") else None return (DiagnosticMessage(Source("py/diagnostics/internal-error", "Internal error in Python extractor"), Severity.ERROR) .with_location(l) .text("Internal error") .attribute("traceback", get_stack_trace_lines()) .attribute("args", exception.args) .telemetry() )