Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[flake8-logging] Add ExcInfoOutsideExceptionHandler (LOG014) #14682

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
154 changes: 154 additions & 0 deletions crates/ruff_linter/resources/test/fixtures/flake8_logging/LOG014.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,154 @@
import logging

# Logging ----------------------------------------------------------------------

logging.exception("foo") # OK
logging.exception("foo", exc_info=False) # OK
logging.exception("foo", exc_info=[]) # OK
logging.exception("foo", exc_info=True) # LOG014
logging.exception("foo", exc_info=[1]) # LOG014

logging.error("foo", exc_info=False) # OK
logging.error("foo", exc_info=True) # LOG014

logging.info("foo", exc_info=False) # OK
logging.info("foo", exc_info=True) # LOG014

try:
a = 1 * 2
except Exception:
logging.exception("foo") # OK
logging.exception("foo", exc_info=False) # OK
logging.exception("foo", exc_info=[]) # OK
logging.exception("foo", exc_info=True) # OK
logging.exception("foo", exc_info=[1]) # OK

logging.error("foo", exc_info=False) # OK
logging.error("foo", exc_info=True) # OK

logging.info("foo", exc_info=False) # OK
logging.info("foo", exc_info=True) # OK

# Logger -----------------------------------------------------------------------

logger = logging.getLogger(__name__)

logger.exception("foo") # OK
logger.exception("foo", exc_info=False) # OK
logger.exception("foo", exc_info=[]) # OK
logger.exception("foo", exc_info=True) # LOG014
logger.exception("foo", exc_info=[1]) # LOG014

logger.error("foo", exc_info=False) # OK
logger.error("foo", exc_info=True) # LOG014

logger.info("foo", exc_info=False) # OK
logger.info("foo", exc_info=True) # LOG014

try:
a = 1 * 2
except Exception:
logger.exception("foo") # OK
logger.exception("foo", exc_info=False) # OK
logger.exception("foo", exc_info=[]) # OK
logger.exception("foo", exc_info=True) # OK
logger.exception("foo", exc_info=[1]) # OK

logger.error("foo", exc_info=False) # OK
logger.error("foo", exc_info=True) # OK

logger.info("foo", exc_info=False) # OK
logger.info("foo", exc_info=True) # OK

# Direct Call ------------------------------------------------------------------

from logging import exception, error, info

exception("foo") # OK
exception("foo", exc_info=False) # OK
exception("foo", exc_info=[]) # OK
exception("foo", exc_info=True) # LOG014
exception("foo", exc_info=[1]) # LOG014

error("foo", exc_info=False) # OK
error("foo", exc_info=True) # LOG014

info("foo", exc_info=False) # OK
info("foo", exc_info=True) # LOG014

try:
a = 1 * 2
except Exception:
exception("foo") # OK
exception("foo", exc_info=False) # OK
exception("foo", exc_info=[]) # OK
exception("foo", exc_info=True) # OK
exception("foo", exc_info=[1]) # OK

error("foo", exc_info=False) # OK
error("foo", exc_info=True) # OK

info("foo", exc_info=False) # OK
info("foo", exc_info=True) # OK

# Fake Call --------------------------------------------------------------------

def wrapper():
exception = lambda *args, **kwargs: None
error = lambda *args, **kwargs: None
info = lambda *args, **kwargs: None

exception("foo") # OK
exception("foo", exc_info=False) # OK
exception("foo", exc_info=[]) # OK
exception("foo", exc_info=True) # OK
exception("foo", exc_info=[1]) # OK

error("foo", exc_info=False) # OK
error("foo", exc_info=True) # OK

info("foo", exc_info=False) # OK
info("foo", exc_info=True) # OK

try:
a = 1 * 2
except Exception:
exception("foo") # OK
exception("foo", exc_info=False) # OK
exception("foo", exc_info=[]) # OK
exception("foo", exc_info=True) # OK
exception("foo", exc_info=[1]) # OK

error("foo", exc_info=False) # OK
error("foo", exc_info=True) # OK

info("foo", exc_info=False) # OK
info("foo", exc_info=True) # OK

# Nested -----------------------------------------------------------------------

def apple_1():
try:
logging.exception("foo", exc_info=True) # LOG014
except Exception:
pass


def apple_2():
def banana():
logging.exception("foo", exc_info=True) # LOG014

try:
banana()
except Exception:
pass


def apple_3():
def banana():
logging.exception("foo", exc_info=True) # LOG014

try:
a = 1 * 2
except Exception:
banana()
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The ecosystem checks are turning up a few instances just like this.

Technically in this case, if we are able to tell that banana() is only ever called from inside an exception handling block, then we could mark this as okay. But I don't think it's possible to check all calling sites?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's possible, but you'd need to move the rule to crates/ruff_linter/src/checkers/ast/analyze/bindings.rs rather than crates/ruff_linter/src/checkers/ast/analyze/expression.rs. The difference is that the rules executed from bindings.rs are run after the entire semantic model has been built, so they have more information available to them in some ways: they're able to iterate through all the references to a binding as well as looking at the original binding itself. You can see an example of how to do it in a PR I merged this morning: #14661.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ahh. I'll revise it to include that check then. Thanks.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

no problem, thanks for the PR!

Copy link
Contributor Author

@snowdrop4 snowdrop4 Dec 2, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Forgive me if I'm misunderstanding, but I don't think moving it to bindings.rs works?

An expression like logging.info("foo", exc_info=True) isn't a binding, so if I move my lint function call to bindings.rs, then the only situation the lint could possibly apply would be x = logging.info("foo", exc_info=True) or (x := logging.info("foo", exc_info=True)), which no one writes.

Is it possible to make a new version of expression.rs that's called after the entire semantic model has been built? I don't think there's any way around calling the lint function on expressions, since the lint is designed to find bad function calls.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

An expression like logging.info("foo", exc_info=True) isn't a binding, so if I move my lint function call to bindings.rs, then the only situation the lint could possibly apply would be x = logging.info("foo", exc_info=True) or (x := logging.info("foo", exc_info=True)), which no one writes.

ah, you're quite right.

I suppose what would be best would be to collect all logging.(...) calls into a Vec stored on this struct as we traverse the AST in https://github.com/astral-sh/ruff/blob/main/crates/ruff_linter/src/checkers/ast/mod.rs. Then after the AST has been fully visited and the SemanticModel has been fully constructed, we can call this rule on each logging(...) call we stored in the Vec.

3 changes: 3 additions & 0 deletions crates/ruff_linter/src/checkers/ast/analyze/expression.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1030,6 +1030,9 @@ pub(crate) fn expression(expr: &Expr, checker: &mut Checker) {
if checker.enabled(Rule::RootLoggerCall) {
flake8_logging::rules::root_logger_call(checker, call);
}
if checker.enabled(Rule::ExcInfoOutsideExceptionHandler) {
flake8_logging::rules::exc_info_outside_exception_handler(checker, call);
}
if checker.enabled(Rule::IsinstanceTypeNone) {
refurb::rules::isinstance_type_none(checker, call);
}
Expand Down
1 change: 1 addition & 0 deletions crates/ruff_linter/src/codes.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1101,6 +1101,7 @@ pub fn code_to_rule(linter: Linter, code: &str) -> Option<(RuleGroup, Rule)> {
(Flake8Logging, "002") => (RuleGroup::Stable, rules::flake8_logging::rules::InvalidGetLoggerArgument),
(Flake8Logging, "007") => (RuleGroup::Stable, rules::flake8_logging::rules::ExceptionWithoutExcInfo),
(Flake8Logging, "009") => (RuleGroup::Stable, rules::flake8_logging::rules::UndocumentedWarn),
(Flake8Logging, "014") => (RuleGroup::Preview, rules::flake8_logging::rules::ExcInfoOutsideExceptionHandler),
(Flake8Logging, "015") => (RuleGroup::Preview, rules::flake8_logging::rules::RootLoggerCall),

_ => return None,
Expand Down
2 changes: 1 addition & 1 deletion crates/ruff_linter/src/registry/rule_set.rs
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@ use ruff_macros::CacheKey;

use crate::registry::Rule;

const RULESET_SIZE: usize = 14;
const RULESET_SIZE: usize = 15;

/// A set of [`Rule`]s.
///
Expand Down
30 changes: 30 additions & 0 deletions crates/ruff_linter/src/rules/flake8_logging/helpers.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,30 @@
use crate::checkers::ast::Checker;
use ruff_python_ast::helpers::Truthiness;
use ruff_python_ast::ExprCall;

fn exc_info_arg_is_(checker: &mut Checker, call: &ExprCall, boolean: bool) -> bool {
call.arguments
.find_keyword("exc_info")
.map(|keyword| &keyword.value)
.is_some_and(|value| {
let truthiness =
Truthiness::from_expr(value, |id| checker.semantic().has_builtin_binding(id));
truthiness.into_bool() == Some(boolean)
})
}

pub(super) fn exc_info_arg_is_falsey(checker: &mut Checker, call: &ExprCall) -> bool {
exc_info_arg_is_(checker, call, false)
}

pub(super) fn exc_info_arg_is_truey(checker: &mut Checker, call: &ExprCall) -> bool {
exc_info_arg_is_(checker, call, true)
}

#[inline]
pub(super) fn is_logger_method_name(attr: &str) -> bool {
matches!(
attr,
"debug" | "info" | "warn" | "warning" | "error" | "critical" | "log" | "exception"
)
}
2 changes: 2 additions & 0 deletions crates/ruff_linter/src/rules/flake8_logging/mod.rs
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
//! Rules from [flake8-logging](https://pypi.org/project/flake8-logging/).
mod helpers;
pub(crate) mod rules;

#[cfg(test)]
Expand Down Expand Up @@ -28,6 +29,7 @@ mod tests {
Ok(())
}

#[test_case(Rule::ExcInfoOutsideExceptionHandler, Path::new("LOG014.py"))]
#[test_case(Rule::RootLoggerCall, Path::new("LOG015.py"))]
fn preview_rules(rule_code: Rule, path: &Path) -> Result<()> {
let snapshot = format!("{}_{}", rule_code.noqa_code(), path.to_string_lossy());
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,102 @@
use crate::checkers::ast::Checker;
use crate::rules::flake8_logging::helpers;
use ruff_diagnostics::{Diagnostic, Violation};
use ruff_macros::{derive_message_formats, ViolationMetadata};
use ruff_python_ast::{self as ast, Expr, ExprCall, Stmt};
use ruff_python_semantic::analyze::logging;
use ruff_python_stdlib::logging::LoggingLevel;
use ruff_text_size::Ranged;

/// ## What it does
/// Checks for cases where a logging call is made with `exc_info` set to `True`,
/// outside of an exception handling block.
///
/// ## Why is this bad?
/// When outside of an exception handling block, the variable holding the
/// exception information will be assigned to `None` as there is no active
/// exception, which then causes the final line of the logging call to contain
/// `NoneType: None`, which is meaningless
///
/// ## Example
/// ```python
/// logging.error("...", exc_info=True)
/// ```
///
/// Either add an exception handling block:
/// ```python
/// try:
/// logging.error("...", exc_info=True)
/// except ...:
/// ...
/// ```
///
/// Or don't set `exc_info` to `True`:
/// logging.error("...")
#[derive(ViolationMetadata)]
pub(crate) struct ExcInfoOutsideExceptionHandler;

impl Violation for ExcInfoOutsideExceptionHandler {
#[derive_message_formats]
fn message(&self) -> String {
"Use of `exc_info` outside an exception handler".to_string()
}
}

/// LOG014
pub(crate) fn exc_info_outside_exception_handler(checker: &mut Checker, call: &ExprCall) {
if is_logging_call(checker, call)
&& helpers::exc_info_arg_is_truey(checker, call)
&& currently_outside_exception_handler(checker)
{
checker.diagnostics.push(Diagnostic::new(
ExcInfoOutsideExceptionHandler,
call.range(),
));
}
}

fn currently_outside_exception_handler(checker: &mut Checker) -> bool {
for parent_stmt in checker.semantic().current_statements() {
if let Stmt::Try(_) = parent_stmt {
return false;
}
}

true
}

fn is_logging_call(checker: &mut Checker, call: &ExprCall) -> bool {
match call.func.as_ref() {
Expr::Attribute(ast::ExprAttribute { attr, .. }) => {
// Match any logging level
if LoggingLevel::from_attribute(attr.as_str()).is_none() {
return false;
}

if !logging::is_logger_candidate(
&call.func,
checker.semantic(),
&checker.settings.logger_objects,
) {
return false;
}
}
Expr::Name(_) => {
if !checker
.semantic()
.resolve_qualified_name(call.func.as_ref())
.is_some_and(|qualified_name| {
matches!(
qualified_name.segments(),
["logging", attr] if helpers::is_logger_method_name(attr)
)
})
{
return false;
}
}
_ => return false,
}

true
}
Original file line number Diff line number Diff line change
@@ -1,13 +1,12 @@
use crate::checkers::ast::Checker;
use crate::rules::flake8_logging::helpers;
use ruff_diagnostics::{Diagnostic, Violation};
use ruff_macros::{derive_message_formats, ViolationMetadata};
use ruff_python_ast::helpers::Truthiness;
use ruff_python_ast::{self as ast, Expr, ExprCall};
use ruff_python_semantic::analyze::logging;
use ruff_python_stdlib::logging::LoggingLevel;
use ruff_text_size::Ranged;

use crate::checkers::ast::Checker;

/// ## What it does
/// Checks for uses of `logging.exception()` with `exc_info` set to `False`.
///
Expand Down Expand Up @@ -73,20 +72,9 @@ pub(crate) fn exception_without_exc_info(checker: &mut Checker, call: &ExprCall)
_ => return,
}

if exc_info_arg_is_falsey(call, checker) {
if helpers::exc_info_arg_is_falsey(checker, call) {
checker
.diagnostics
.push(Diagnostic::new(ExceptionWithoutExcInfo, call.range()));
}
}

fn exc_info_arg_is_falsey(call: &ExprCall, checker: &mut Checker) -> bool {
call.arguments
.find_keyword("exc_info")
.map(|keyword| &keyword.value)
.is_some_and(|value| {
let truthiness =
Truthiness::from_expr(value, |id| checker.semantic().has_builtin_binding(id));
truthiness.into_bool() == Some(false)
})
}
2 changes: 2 additions & 0 deletions crates/ruff_linter/src/rules/flake8_logging/rules/mod.rs
Original file line number Diff line number Diff line change
@@ -1,10 +1,12 @@
pub(crate) use direct_logger_instantiation::*;
pub(crate) use exc_info_outside_exception_handler::*;
pub(crate) use exception_without_exc_info::*;
pub(crate) use invalid_get_logger_argument::*;
pub(crate) use root_logger_call::*;
pub(crate) use undocumented_warn::*;

mod direct_logger_instantiation;
mod exc_info_outside_exception_handler;
mod exception_without_exc_info;
mod invalid_get_logger_argument;
mod root_logger_call;
Expand Down
Loading