From 22da1831ec5be1b28e9fac23f40fb130899b77ec Mon Sep 17 00:00:00 2001 From: Marshall Hallenbeck Date: Tue, 26 Mar 2024 21:55:05 -0400 Subject: [PATCH] fix(logging): do not double log output in debug mode; properly show calling file & lineno for such messages --- nxc/logger.py | 67 ++++++++++++++++++++++++++++++++++++++++++--------- 1 file changed, 55 insertions(+), 12 deletions(-) diff --git a/nxc/logger.py b/nxc/logger.py index 5c0f40d6..8e580317 100755 --- a/nxc/logger.py +++ b/nxc/logger.py @@ -9,6 +9,49 @@ from termcolor import colored from datetime import datetime from rich.text import Text from rich.logging import RichHandler +import functools +import inspect + + +def create_temp_logger(caller_frame, formatted_text, args, kwargs): + """Create a temporary logger for emitting a log where we need to override the calling file & line number, since these are obfuscated""" + temp_logger = logging.getLogger("temp") + formatter = logging.Formatter("%(message)s", datefmt="[%X]") + handler = SmartDebugRichHandler(formatter=formatter) + handler.handle(LogRecord(temp_logger.name, logging.DEBUG, caller_frame.f_code.co_filename, caller_frame.f_lineno, formatted_text, args, kwargs, caller_frame=caller_frame)) + + +class SmartDebugRichHandler(RichHandler): + """Custom logging handler for when we want to log normal messages to DEBUG and not double log""" + def __init__(self, formatter=None, *args, **kwargs): + super().__init__(*args, **kwargs) + if formatter is not None: + self.setFormatter(formatter) + + def emit(self, record): + """Overrides the emit method of the RichHandler class so we can set the proper pathname and lineno""" + if hasattr(record, "caller_frame"): + frame_info = inspect.getframeinfo(record.caller_frame) + record.pathname = frame_info.filename + record.lineno = frame_info.lineno + super().emit(record) + + +def no_debug(func): + """Stops logging non-debug messages when we are in debug mode + It creates a temporary logger and logs the message to the console and file + This is so we don't get both normal output AND debugging output, AND so we get the proper log calling file & line number + """ + @functools.wraps(func) + def wrapper(self, msg, *args, **kwargs): + if self.logger.getEffectiveLevel() >= logging.INFO: + return func(self, msg, *args, **kwargs) + else: + formatted_text = Text.from_ansi(self.format(msg, *args, **kwargs)[0]) + caller_frame = inspect.currentframe().f_back + create_temp_logger(caller_frame, formatted_text, args, kwargs) + self.log_console_to_file(formatted_text, *args, **kwargs) + return wrapper class NXCAdapter(logging.LoggerAdapter): @@ -54,6 +97,7 @@ class NXCAdapter(logging.LoggerAdapter): return (f"{module_name:<24} {self.extra['host']:<15} {self.extra['port']:<6} {self.extra['hostname'] if self.extra['hostname'] else 'NONE':<16} {msg}", kwargs) + @no_debug def display(self, msg, *args, **kwargs): """Display text to console, formatted for nxc""" msg, kwargs = self.format(f"{colored('[*]', 'blue', attrs=['bold'])} {msg}", kwargs) @@ -61,13 +105,15 @@ class NXCAdapter(logging.LoggerAdapter): nxc_console.print(text, *args, **kwargs) self.log_console_to_file(text, *args, **kwargs) + @no_debug def success(self, msg, color="green", *args, **kwargs): - """Print some sort of success to the user""" + """Prints some sort of success to the user""" msg, kwargs = self.format(f"{colored('[+]', color, attrs=['bold'])} {msg}", kwargs) text = Text.from_ansi(msg) nxc_console.print(text, *args, **kwargs) self.log_console_to_file(text, *args, **kwargs) + @no_debug def highlight(self, msg, *args, **kwargs): """Prints a completely yellow highlighted message to the user""" msg, kwargs = self.format(f"{colored(msg, 'yellow', attrs=['bold'])}", kwargs) @@ -75,6 +121,7 @@ class NXCAdapter(logging.LoggerAdapter): nxc_console.print(text, *args, **kwargs) self.log_console_to_file(text, *args, **kwargs) + @no_debug def fail(self, msg, color="red", *args, **kwargs): """Prints a failure (may or may not be an error) - e.g. login creds didn't work""" msg, kwargs = self.format(f"{colored('[-]', color, attrs=['bold'])} {msg}", kwargs) @@ -88,16 +135,12 @@ class NXCAdapter(logging.LoggerAdapter): If debug or info logging is not enabled, we still want display/success/fail logged to the file specified, so we create a custom LogRecord and pass it to all the additional handlers (which will be all the file handlers) """ - if self.logger.getEffectiveLevel() >= logging.INFO: - # will be 0 if it's just the console output, so only do this if we actually have file loggers - if len(self.logger.handlers): - try: - for handler in self.logger.handlers: - handler.handle(LogRecord("nxc", 20, "", kwargs, msg=text, args=args, exc_info=None)) - except Exception as e: - self.logger.fail(f"Issue while trying to custom print handler: {e}") - else: - self.logger.info(text) + if self.logger.getEffectiveLevel() >= logging.INFO and len(self.logger.handlers): # will be 0 if it's just the console output, so only do this if we actually have file loggers + try: + for handler in self.logger.handlers: + handler.handle(LogRecord("nxc", 20, "", kwargs, msg=text, args=args, exc_info=None)) + except Exception as e: + self.logger.fail(f"Issue while trying to custom print handler: {e}") def add_file_log(self, log_file=None): file_formatter = TermEscapeCodeFormatter("%(asctime)s - %(levelname)s - %(message)s") @@ -131,7 +174,7 @@ class NXCAdapter(logging.LoggerAdapter): datetime.now().strftime("%Y-%m-%d"), f"log_{datetime.now().strftime('%Y-%m-%d-%H-%M-%S')}.log", ) - + class TermEscapeCodeFormatter(logging.Formatter): """A class to strip the escape codes for logging to files"""