From d9a188a06813cd524d2ceff757c2910b079666a6 Mon Sep 17 00:00:00 2001 From: Mikhail Burshteyn Date: Fri, 17 Aug 2018 17:35:17 +0300 Subject: [PATCH] Check for usage of exceptions in logging arguments --- README.md | 3 + logging_format/tests/test_visitor.py | 231 +++++++++++++++++++++++++++ logging_format/violations.py | 5 + logging_format/visitor.py | 94 +++++++++++ 4 files changed, 333 insertions(+) diff --git a/README.md b/README.md index c050864..d566d40 100644 --- a/README.md +++ b/README.md @@ -50,6 +50,9 @@ In some cases you may want to log sensitive data only in debugging senarios. Th - `G004` Logging statements should not use `f"..."` for their first argument (only in Python 3.6+) - `G010` Logging statements should not use `warn` (use `warning` instead) - `G100` Logging statements should not use `extra` arguments unless whitelisted + - `G200` Logging statements should not include the exception in logged string (use `exception` or `exc_info=True`) + - `G201` Logging statements should not use `error(..., exc_info=True)` (use `exception(...)` instead) + - `G202` Logging statements should not use redundant `exc_info=True` in `exception` These violations are disabled by default. To enable them for your project, specify the code(s) in your `setup.cfg`: diff --git a/logging_format/tests/test_visitor.py b/logging_format/tests/test_visitor.py index 11a7e6c..e172be6 100644 --- a/logging_format/tests/test_visitor.py +++ b/logging_format/tests/test_visitor.py @@ -22,6 +22,9 @@ FSTRING_VIOLATION, WARN_VIOLATION, WHITELIST_VIOLATION, + EXCEPTION_VIOLATION, + ERROR_EXC_INFO_VIOLATION, + REDUNDANT_EXC_INFO_VIOLATION, ) from logging_format.visitor import LoggingVisitor from logging_format.whitelist import Whitelist @@ -328,3 +331,231 @@ def test_warnings(): visitor.visit(tree) assert_that(visitor.violations, is_(empty())) + + +def test_exception_standard(): + """ + In an except block, exceptions should be logged using .exception(). + + """ + tree = parse(dedent("""\ + import logging + + try: + pass + except Exception: + logging.exception('Something bad has happened') + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, is_(empty())) + + +def test_exception_warning(): + """ + In an except block, logging exceptions using exc_info=True is ok. + + """ + tree = parse(dedent("""\ + import logging + + try: + pass + except Exception: + logging.warning('Something bad has happened', exc_info=True) + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, is_(empty())) + + +def test_exception_attribute_as_main_arg(): + """ + In an except block, passing an exception attribute into logging as main argument is ok. + + """ + tree = parse(dedent("""\ + import logging + + class CustomException(Exception): + def __init__(self, custom_arg): + self.custom_arg = custom_arg + + try: + pass + except CustomException as e: + logging.error(e.custom_arg) + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, is_(empty())) + + +def test_exception_attribute_as_formatting_arg(): + """ + In an except block, passing an exception attribute into logging as a formatting argument is ok. + + """ + tree = parse(dedent("""\ + import logging + + class CustomException(Exception): + def __init__(self, custom_arg): + self.custom_arg = custom_arg + + try: + pass + except CustomException as e: + logging.error('Custom exception has occurred: %s', e.custom_arg) + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, is_(empty())) + + +def test_exception_attribute_in_extra(): + """ + In an except block, passing an exception attribute into logging as a value of extra dict is ok. + + """ + tree = parse(dedent("""\ + import logging + + class CustomException(Exception): + def __init__(self, custom_arg): + self.custom_arg = custom_arg + + try: + pass + except CustomException as e: + logging.error('Custom exception has occurred: {custom_arg}', extra=dict(custom_arg=e.custom_arg)) + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, is_(empty())) + + +def test_exception_as_main_arg(): + """ + In an except block, passing the exception into logging as main argument is not ok. + + """ + tree = parse(dedent("""\ + import logging + + try: + pass + except Exception as e: + logging.exception(e) + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, has_length(1)) + assert_that(visitor.violations[0][1], is_(equal_to(EXCEPTION_VIOLATION))) + + +def test_exception_as_formatting_arg(): + """ + In an except block, passing the exception into logging as a formatting argument is not ok. + + """ + tree = parse(dedent("""\ + import logging + + try: + pass + except Exception as e: + logging.exception('Exception occurred: %s', str(e)) + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, has_length(1)) + assert_that(visitor.violations[0][1], is_(equal_to(EXCEPTION_VIOLATION))) + + +def test_exception_in_extra(): + """ + In an except block, passing the exception into logging as a value of extra dict is not ok. + + """ + tree = parse(dedent("""\ + import logging + + try: + pass + except Exception as e: + logging.exception('Exception occurred: {exc}', extra=dict(exc=e)) + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, has_length(1)) + assert_that(visitor.violations[0][1], is_(equal_to(EXCEPTION_VIOLATION))) + + +def test_nested_exception(): + """ + In a nested except block, using the exception from an outer except block is not ok. + + """ + tree = parse(dedent("""\ + import logging + + try: + pass + except Exception as e1: + try: + pass + except Exception as e2: + logging.exception(e1) + logging.exception(e1) + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, has_length(2)) + assert_that(visitor.violations[0][1], is_(equal_to(EXCEPTION_VIOLATION))) + assert_that(visitor.violations[1][1], is_(equal_to(EXCEPTION_VIOLATION))) + + +def test_error_exc_info(): + """ + .error(..., exc_info=True) should not be used in favor of .exception(...). + + """ + + tree = parse(dedent("""\ + import logging + + logging.error('Hello World', exc_info=True) + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, has_length(1)) + assert_that(visitor.violations[0][1], is_(equal_to(ERROR_EXC_INFO_VIOLATION))) + + +def test_exception_exc_info(): + """ + .exception(..., exc_info=True) is redundant. + + """ + + tree = parse(dedent("""\ + import logging + + logging.exception('Hello World', exc_info=True) + """)) + visitor = LoggingVisitor() + visitor.visit(tree) + + assert_that(visitor.violations, has_length(1)) + assert_that(visitor.violations[0][1], is_(equal_to(REDUNDANT_EXC_INFO_VIOLATION))) diff --git a/logging_format/violations.py b/logging_format/violations.py index 20e7f68..89d9712 100644 --- a/logging_format/violations.py +++ b/logging_format/violations.py @@ -14,3 +14,8 @@ WARN_VIOLATION = "G010 Logging statement uses 'warn' instead of 'warning'" WHITELIST_VIOLATION = "G100 Logging statement uses non-whitelisted extra keyword argument: {}" + +EXCEPTION_VIOLATION = "G200 Logging statement uses exception in arguments" + +ERROR_EXC_INFO_VIOLATION = "G201 Logging: .exception(...) should be used instead of .error(..., exc_info=True)" +REDUNDANT_EXC_INFO_VIOLATION = "G202 Logging statement has redundant exc_info" diff --git a/logging_format/visitor.py b/logging_format/visitor.py index 09e19ed..2faca21 100644 --- a/logging_format/visitor.py +++ b/logging_format/visitor.py @@ -6,9 +6,11 @@ from ast import ( Add, + Call, keyword, iter_child_nodes, Mod, + Name, NodeVisitor, ) @@ -19,6 +21,9 @@ FSTRING_VIOLATION, WARN_VIOLATION, WHITELIST_VIOLATION, + EXCEPTION_VIOLATION, + ERROR_EXC_INFO_VIOLATION, + REDUNDANT_EXC_INFO_VIOLATION, ) if version_info >= (3, 6): @@ -44,6 +49,7 @@ def __init__(self, whitelist=None): self.current_logging_argument = None self.current_logging_level = None self.current_extra_keyword = None + self.current_except_names = [] self.violations = [] self.whitelist = whitelist @@ -86,9 +92,13 @@ def visit_Call(self, node): if logging_level == "warn": self.violations.append((node, WARN_VIOLATION)) + self.check_exc_info(node) + for index, child in enumerate(iter_child_nodes(node)): if index == 1: self.current_logging_argument = child + if index >= 1: + self.check_exception_arg(child) if index > 1 and isinstance(child, keyword) and child.arg == "extra": self.current_extra_keyword = child @@ -125,6 +135,10 @@ def visit_Dict(self, node): continue self.violations.append((self.current_logging_call, WHITELIST_VIOLATION.format(key.s))) + if self.should_check_extra_exception(node): + for value in node.values: + self.check_exception_arg(value) + super(LoggingVisitor, self).generic_visit(node) def visit_JoinedStr(self, node): @@ -147,7 +161,25 @@ def visit_keyword(self, node): if self.should_check_whitelist(node): if node.arg not in self.whitelist and not node.arg.startswith("debug_"): self.violations.append((self.current_logging_call, WHITELIST_VIOLATION.format(node.arg))) + + if self.should_check_extra_exception(node): + self.check_exception_arg(node.value) + + super(LoggingVisitor, self).generic_visit(node) + + def visit_ExceptHandler(self, node): + """ + Process except blocks. + + """ + name = self.get_except_handler_name(node) + if not name: + super(LoggingVisitor, self).generic_visit(node) + return + + self.current_except_names.append(name) super(LoggingVisitor, self).generic_visit(node) + self.current_except_names.pop() def detect_logging_level(self, node): """ @@ -183,3 +215,65 @@ def should_check_whitelist(self, node): self.whitelist is not None, ) ) + + def should_check_extra_exception(self, node): + return all( + ( + self.within_logging_statement(), + self.within_extra_keyword(node), + len(self.current_except_names) > 0, + ) + ) + + def get_except_handler_name(self, node): + """ + Helper to get the exception name from an ExceptHandler node in both py2 and py3. + + """ + name = node.name + if not name: + return None + + if version_info < (3,): + return name.id + return name + + def is_bare_exception(self, node): + """ + Checks if the node is a bare exception name from an except block. + + """ + return isinstance(node, Name) and node.id in self.current_except_names + + def is_str_exception(self, node): + """ + Checks if the node is the expression str(e) or unicode(e), where e is an exception name from an except block + + """ + return ( + isinstance(node, Call) + and isinstance(node.func, Name) + and node.func.id in ('str', 'unicode') + and node.args + and self.is_bare_exception(node.args[0]) + ) + + def check_exception_arg(self, node): + if self.is_bare_exception(node) or self.is_str_exception(node): + self.violations.append((self.current_logging_call, EXCEPTION_VIOLATION)) + + def check_exc_info(self, node): + """ + Reports a violation if exc_info keyword is used with logging.error or logging.exception. + + """ + if self.current_logging_level not in ('error', 'exception'): + return + + for kw in node.keywords: + if kw.arg == 'exc_info': + if self.current_logging_level == 'error': + violation = ERROR_EXC_INFO_VIOLATION + else: + violation = REDUNDANT_EXC_INFO_VIOLATION + self.violations.append((node, violation))