python-logging-guide.md

Python Logging Guide

Logging patterns for Python applications to ensure consistent, debuggable, and production-ready logging.

Quick Reference

Question	Answer
When to configure logging	Application entry point only (main.py)
Library logging configuration	Never - libraries ONLY get logger with __name__
Exception logging	Use logger.exception() in except blocks
Message formatting	F-strings for INFO+, %s for expensive DEBUG
Where to log exceptions	Once at system boundaries (handlers, runners)
Secret handling	Log length/presence, never actual values

Canonical pattern:

# main.py - Configure once at startuplogging.basicConfig(
format='%(asctime)s %(levelname)-8s [%(name)s:%(lineno)d] %(message)s',
level=logging.INFO,
datefmt='%Y-%m-%d %H:%M:%S'
)
# any_module.py - Get logger at import timelogger=logging.getLogger(__name__)

Log Level Reference

Level	Use When	Example
DEBUG	Development diagnostics, verbose details	logger.debug(f"SQL query: {query}")
INFO	Production status, milestones, state changes	logger.info("Server started on port 8080")
WARNING	Unexpected but recoverable, deprecated usage	logger.warning("Cache miss, falling back to DB")
ERROR	Failure that needs attention, request failed	logger.error("Payment gateway timeout")
CRITICAL	System failure, data loss, requires immediate action	logger.critical("Out of memory")

Configuration Rules

RULE python-logging/configure-once-in-main (MUST)

Owner: python-quality-assistant Applies when: a Python file in library code (modules imported by application code, intended for reuse across applications) calls logging.basicConfig() or adds handlers to the root logger. Exempt: the application entry point (main.py / __main__.py / cli.py) AND application-private helper modules wired from the entry point exclusively for configuration (e.g. logging_setup.py — see the next section), since those are part of the entry-point configuration surface, not library code. Enforcement: judgment (semantic — distinguishing library code from application-private configuration helpers requires reading the import graph; ast-grep can flag every non-entry-point logging.basicConfig call as a first-pass filter, but the agent must rule out the helper-module exemption case) Trigger: **/*.py Why: basicConfig is a one-shot global root-logger setup. Calling it from library code produces three failure modes: (1) first import wins, so the library's config silently overrides the application's choice depending on import order; (2) repeated calls add duplicate handlers, doubling every log line; (3) applications can't change log level without code edits in libraries they don't control. Libraries call logging.getLogger(__name__) and emit; configuration is the application's responsibility, and the application does it exactly once.

Bad

# mylib/service.py — library configures logging — wrongimportlogginglogging.basicConfig(level=logging.INFO) # first import wins, overrides applogger=logging.getLogger(__name__)
classUserService: ...

Good

# main.py — application entry point, configure onceimportloggingdefmain():
logging.basicConfig(
format='%(asctime)s %(levelname)-8s [%(name)s:%(lineno)d] %(message)s',
level=logging.INFO,
)
# ... rest of app wiring ...if__name__=="__main__":
main()
# mylib/service.py — library only gets a logger, never configuresimportlogginglogger=logging.getLogger(__name__)
classUserService:
defprocess(self):
logger.info("processing user")

Extract Logging Configuration to Dedicated Module

Constraint: Applications with complex logging needs (multiple handlers, conditional configuration) SHOULD extract logging setup to dedicated logging_setup.py module.

Rationale: Keeps main.py focused on application flow; makes logging configuration reusable and testable.

Examples:

# [GOOD] - Extracted logging setup# src/package/logging_setup.py"""Logging configuration."""importloggingimportsysfromlogging.handlersimportRotatingFileHandlerfrompathlibimportPathdefconfigure_logging(
level: str="INFO",
log_file: str|None=None,
) ->None:
"""Configure application logging. Args: level: Log level (DEBUG, INFO, WARNING, ERROR, CRITICAL) log_file: Optional file path for log output """log_level=getattr(logging, level.upper(), logging.INFO)
# Base formatlog_format="%(asctime)s %(levelname)-8s [%(name)s:%(lineno)d] %(message)s"date_format="%Y-%m-%d %H:%M:%S"handlers: list[logging.Handler] = []
# Console handlerconsole_handler=logging.StreamHandler(sys.stdout)
console_handler.setLevel(log_level)
console_handler.setFormatter(logging.Formatter(log_format, date_format))
handlers.append(console_handler)
# Optional file handleriflog_file:
log_path=Path(log_file)
log_path.parent.mkdir(parents=True, exist_ok=True)
file_handler=RotatingFileHandler(
log_file,
maxBytes=10_000_000, # 10MBbackupCount=5,
encoding="utf-8",
)
file_handler.setLevel(log_level)
file_handler.setFormatter(logging.Formatter(log_format, date_format))
handlers.append(file_handler)
# Configure root loggerlogging.basicConfig(
level=log_level,
format=log_format,
datefmt=date_format,
handlers=handlers,
force=True, # Override any existing configuration
)
# src/package/__main__.py"""Entry point."""importloggingfrompackage.logging_setupimportconfigure_logginglogger=logging.getLogger(__name__)
defmain() ->None:
"""Main entry point."""args=parse_args()
# Configure logging onceconfigure_logging(
level=args.log_level,
log_file=args.log_fileifargs.command=="backup"elseNone,
)
logger.info("Application started")
# ... rest of application# [BAD] - Inline logging setup in __main__.pydefmain() ->None:
args=parse_args()
# Complex logging setup cluttering main()log_format="%(asctime)s %(levelname)-8s [%(name)s:%(lineno)d] %(message)s"handlers= []
console=logging.StreamHandler(sys.stdout)
console.setFormatter(logging.Formatter(log_format))
handlers.append(console)
ifargs.log_file:
file_handler=RotatingFileHandler(args.log_file, maxBytes=10_000_000)
file_handler.setFormatter(logging.Formatter(log_format))
handlers.append(file_handler)
logging.basicConfig(level=args.log_level, handlers=handlers)
# ... application logic

Benefits:

• Separates configuration from application logic
• Reusable across entry points (CLI, tests, services)
• Testable in isolation
• Easier to maintain and modify

When to extract:

• Multiple handlers (console + file)
• Conditional handler configuration
• Custom formatters per handler
• Complex log level logic

Reference: iphone-image-backup project (src/iphone_backup/logging_setup.py) demonstrates extracted logging configuration.

Never Combine basicConfig with Manual Handlers

Constraint: Code MUST use either basicConfig() OR manual handler setup, never both.

Rationale: Combining both creates duplicate handlers that log every message twice.

Examples:

# [BAD] Mixing configuration methodslogging.basicConfig(level=logging.INFO) # Creates default handlerlogging.root.addHandler(my_handler) # Adds second handler - duplicates!# [GOOD] basicConfig only (simple apps)logging.basicConfig(
level=logging.INFO,
format='%(asctime)s %(levelname)s %(message)s'
)
# [GOOD] Manual handlers only (advanced apps)handler=logging.StreamHandler()
handler.setFormatter(logging.Formatter('%(asctime)s %(message)s'))
logging.root.addHandler(handler)
logging.root.setLevel(logging.INFO)

Use Module-Level Loggers at Import Time

Constraint: Code MUST define loggers at module level using logger = logging.getLogger(__name__), not inside functions.

Rationale: Module-level loggers enable hierarchical naming, per-module configuration, and easier log filtering.

Examples:

# [GOOD] Module-level logger# users/service.pyimportlogginglogger=logging.getLogger(__name__) # Creates 'users.service' loggerclassUserService:
defcreate_user(self, username: str):
logger.info(f"Creating user: username={username}")
# [BAD] Logger inside functionclassUserService:
defcreate_user(self, username: str):
logger=logging.getLogger(__name__) # Recreated every calllogger.info(f"Creating user: username={username}")
# [GOOD] Per-module level configuration# main.pylogging.basicConfig(level=logging.INFO)
logging.getLogger('users.service').setLevel(logging.DEBUG)
logging.getLogger('database').setLevel(logging.WARNING)

Include Structured Format with Context

Constraint:basicConfig() format MUST include timestamp, level, logger name, and line number in pattern %(asctime)s %(levelname)-8s [%(name)s:%(lineno)d] %(message)s.

Rationale: Structured format enables debugging by showing when, where, and what severity for every log entry.

Examples:

# [GOOD] Complete structured formatlogging.basicConfig(
format='%(asctime)s %(levelname)-8s [%(name)s:%(lineno)d] %(message)s',
level=logging.INFO,
datefmt='%Y-%m-%d %H:%M:%S'
)
logger=logging.getLogger(__name__)
logger.info(f"Processing order: order_id={order_id}, total={total}")
# Output: 2026-01-05 14:23:15 INFO [orders.service:45] Processing order: order_id=12345, total=99.99# [BAD] Missing contextlogging.basicConfig(format='%(message)s') # No timestamp, level, location# [BAD] Non-ISO date formatlogging.basicConfig(datefmt='%m/%d/%y') # Use %Y-%m-%d %H:%M:%S

Exception Logging Rules

Use logger.exception() for Exception Logging

Constraint: Code MUST use logger.exception() inside except blocks to automatically include stack traces.

Rationale:logger.exception() automatically captures and formats the full stack trace without manual exc_info=True.

Examples:

# [GOOD] logger.exception() in except blocktry:
result=risky_operation()
exceptValueError:
logger.exception("Validation failed") # Auto-includes stack traceraise# [GOOD] Alternative with exc_info=Truetry:
result=risky_operation()
exceptExceptionase:
logger.error(f"Operation failed: {e}", exc_info=True)
raise# [BAD] Missing stack tracetry:
result=risky_operation()
exceptExceptionase:
logger.error(f"Failed: {e}") # No stack trace for debugging# [GOOD] Stack trace outside exception contextlogger.warning("Deprecated code path", stack_info=True)

Log Exceptions Once at System Boundaries

Constraint: Code MUST log exceptions at system boundaries (API handlers, job runners, main loops) and MUST NOT log the same exception at multiple layers.

Rationale: Logging at every layer creates duplicate log entries for the same error, making debugging harder.

Examples:

# [BAD] Logging at every layerdefservice_method():
try:
db.execute(query)
exceptExceptionase:
logger.error(f"DB error: {e}", exc_info=True) # Logged hereraisedefhandler():
try:
service_method()
exceptExceptionase:
logger.error(f"Handler error: {e}", exc_info=True) # AND here - duplicate!raise# [GOOD] Log once at boundarydefservice_method():
db.execute(query) # Let exception propagatedefhandler():
try:
service_method()
exceptException:
logger.exception("Failed to process request") # Log oncereturnerror_response()

Message Formatting Rules

Use F-Strings for INFO and Above

Constraint: Code MUST use f-strings for INFO/WARNING/ERROR/CRITICAL level messages.

Rationale: F-strings provide clarity and have no performance impact at these levels since they're always evaluated.

Examples:

# [GOOD] F-strings for INFO and abovelogger.info(f"User {username} logged in")
logger.warning(f"Rate limit: {current}/{max}")
logger.error(f"Failed to connect: {connection_error}")
# [BAD] Comma syntax without placeholderslogger.warning("Failed to connect", connection_error) # Only logs first arg# [GOOD] Comma syntax with % placeholders (works but less clear)logger.warning("Failed to connect: %s", connection_error)

RULE python-logging/lazy-evaluation-for-debug (MUST)

Owner: python-quality-assistant Applies when: a Python logger.debug(...) / logger.log(logging.DEBUG, ...) call passes an f-string whose interpolation calls an expensive function (serializer, JSON dump, network fetch, large-collection traversal) instead of using %s placeholders with deferred arguments. Enforcement: rules/python/lazy-evaluation-for-debug.yml flags any logger.debug(...) call whose argument list contains an f-string (first-pass filter). Trivial f-strings like logger.debug(f"count={count}") fire — the agent makes the expensive-vs-trivial judgment and dismisses cheap interpolations. Why: F-strings interpolate immediately at function-call time. With logger.debug(f"...{expensive(x)}..."), expensive(x) runs every call, even when DEBUG is filtered out and the message is discarded. logger.debug("... %s ...", expensive(x)) defers expensive(x) to the logging library, which only evaluates arguments when the level is enabled. In hot paths with DEBUG-by-default-off production, the difference between "free" and "this expensive call runs millions of times for log lines no one sees" is measurable. The isEnabledFor(logging.DEBUG) guard is the explicit alternative; %s is the implicit-defer pattern that scales.

Bad

# F-string forces expensive_serialization to run on every call,# even when DEBUG is filtered out and the message is discardedlogger.debug(f"Details: {expensive_serialization(large_object)}")

Good

# %s placeholder defers evaluation to the logging library — runs only if DEBUG enabledlogger.debug("Details: %s", expensive_serialization(large_object))
# Explicit guard — same effect, more readable when you also need f-string featuresiflogger.isEnabledFor(logging.DEBUG):
logger.debug(f"Details: {expensive_serialization(large_object)}")

Include Semantic Context in Messages

Constraint: Log messages MUST include business identifiers using key=value format (e.g., order_id={order_id}).

Rationale: Structured key=value format enables log parsing, filtering, and correlation across requests.

Examples:

# [GOOD] Structured context with identifierslogger.info(f"Processing order: order_id={order_id}, user_id={user_id}")
logger.info(f"Order completed: order_id={order_id}, total={total}, items={len(items)}")
# [BAD] Unstructured messagelogger.info(f"Processing order {order_id} for user {user_id}") # Harder to parse# [GOOD] Using extra={} for structured contextlogger.info(
"Order processed",
extra={
"order_id": order_id,
"user_id": user_id,
"total": total,
"items": len(items)
}
)

Security Rules

Never Log Secret Values

Constraint: Code MUST NOT log passwords, tokens, API keys, or other secrets. Code MUST log length or presence instead.

Rationale: Logs may be stored insecurely or sent to third-party aggregation systems, exposing credentials.

Examples:

# [BAD] Logging secretslogger.info(f"User login: username={username}, password={password}")
logger.debug(f"API request: Authorization: Bearer {api_token}")
# [GOOD] Log safe information onlylogger.info(f"User login: username={username}")
logger.debug(f"API request authenticated: token_length={len(api_token)}")
logger.info(f"Password configured: {passwordisnotNone}")
# [GOOD] Mask sensitive datalogger.info(f"Credit card: {card_number[:4]}****{card_number[-4:]}")

Handle None Values Safely

Constraint: Code MUST check for None before operations like len() on potentially missing values.

Rationale: Logging crashes on None values defeat the purpose of diagnostic logging.

Examples:

password=os.getenv("PASSWORD") # May return None# [BAD] Unsafe None handlinglogger.info(f"Password length: {len(password)}") # Crashes if None# [GOOD] Safe None handlinglogger.info(f"Password length: {len(password) ifpasswordelse0}")
logger.info(f"Password configured: {passwordisnotNone}")

Log Level Usage Rules

Use Appropriate Log Levels

Constraint: Code MUST use DEBUG for diagnostics, INFO for status, WARNING for unexpected-but-recoverable, ERROR for failures, CRITICAL for system failures.

Rationale: Consistent levels enable proper filtering and alerting in production.

Examples:

# [GOOD] Appropriate level usagelogger.debug(f"Processing user_id={user_id}, batch_size={len(items)}")
logger.info("Database migration completed successfully")
logger.warning(f"API rate limit approaching: {current_rate}/{max_rate}")
logger.error(f"Failed to send email to {email}: {error}")
logger.critical("Database connection pool exhausted, shutting down")
# [BAD] Wrong levelslogger.info("SQL query: SELECT * FROM users WHERE id=?") # Use DEBUGlogger.error("Cache miss, falling back to DB") # Use WARNING

Performance Rules

Avoid Logging in Tight Loops

Constraint: Code MUST NOT log on every iteration of large loops. Code MUST log summary or use sampling instead.

Rationale: High-frequency logging creates storage/performance issues and makes logs unsearchable.

Examples:

# [BAD] Logging every iterationforiteminlarge_list: # 10,000 itemslogger.info(f"Processing {item}") # 10,000 log entriesprocess(item)
# [GOOD] Log summarylogger.info(f"Processing {len(large_list)} items")
foriteminlarge_list:
process(item)
logger.info(f"Completed processing {len(large_list)} items")
# [GOOD] Sample high-frequency eventssample_rate=0.01# 1%foriteminlarge_list:
ifrandom.random() <sample_rate:
logger.debug(f"Processing {item}")
process(item)

Disable Propagation When Adding Child Handlers

Constraint: Code that adds handlers to child loggers MUST set propagate = False to prevent duplicate logs.

Rationale: Child loggers propagate to root by default, causing messages to be logged twice when both have handlers.

Examples:

# [BAD] Child handler without disabling propagationchild_logger=logging.getLogger('myapp.service')
child_logger.addHandler(my_handler) # Logs go here AND to root# [GOOD] Disable propagationchild_logger=logging.getLogger('myapp.service')
child_logger.addHandler(my_handler)
child_logger.propagate=False# Prevent duplicate logs# [BETTER] Only add handlers to root loggerlogging.root.addHandler(my_handler)

Production Patterns

Structured Logging with JSON Format

Constraint: Production systems with log aggregation SHOULD use JSON formatters to output machine-parseable logs.

Rationale: JSON format enables automated parsing, filtering, and analysis in log aggregation systems.

Examples:

# [GOOD] JSON formatter for productionimportjsonfromdatetimeimportdatetimeclassJsonFormatter(logging.Formatter):
defformat(self, record):
log_data= {
'timestamp': datetime.utcnow().isoformat(),
'level': record.levelname,
'logger': record.name,
'message': record.getMessage(),
'module': record.module,
'function': record.funcName,
'line': record.lineno,
}
# Include extra fieldsforkey, valueinrecord.__dict__.items():
ifkeynotin ['name', 'msg', 'args', 'created', 'filename', 'funcName',
'levelname', 'levelno', 'lineno', 'module', 'msecs',
'message', 'pathname', 'process', 'processName',
'relativeCreated', 'thread', 'threadName', 'exc_info',
'exc_text', 'stack_info']:
log_data[key] =valueifrecord.exc_info:
log_data['exception'] =self.formatException(record.exc_info)
returnjson.dumps(log_data)
# Configure with manual handlers (not basicConfig)handler=logging.StreamHandler()
handler.setFormatter(JsonFormatter())
logging.root.addHandler(handler)
logging.root.setLevel(logging.INFO)

Use Correlation IDs for Distributed Systems

Constraint: Distributed systems MUST include request/correlation IDs in all log messages using ContextVars.

Rationale: Correlation IDs enable tracing requests across service boundaries and async operations.

Examples:

# [GOOD] Correlation ID with ContextVarsimportuuidfromcontextvarsimportContextVarrequest_id_var: ContextVar[str] =ContextVar('request_id', default='')
classRequestIdFilter(logging.Filter):
deffilter(self, record):
record.request_id=request_id_var.get()
returnTruelogging.basicConfig(
format='%(asctime)s [%(request_id)s] %(levelname)s %(message)s',
)
logger=logging.getLogger(__name__)
logger.addFilter(RequestIdFilter())
defhandle_request(request):
request_id_var.set(str(uuid.uuid4()))
logger.info(f"Processing request: path={request.path}")
# All logs in this context include request_id

Use LoggerAdapter for Repeated Context

Constraint: Code that logs multiple messages with the same context (user_id, order_id, request_id) SHOULD use LoggerAdapter.

Rationale: LoggerAdapter automatically injects context into every message, reducing repetition and errors.

Examples:

# [GOOD] LoggerAdapter for repeated contextclassOrderAdapter(logging.LoggerAdapter):
defprocess(self, msg, kwargs):
returnf"[order_id={self.extra['order_id']}] {msg}", kwargsdefprocess_order(order_id: str):
order_logger=OrderAdapter(logger, {"order_id": order_id})
order_logger.info("Processing order")
# Logs: [order_id=12345] Processing orderorder_logger.info("Order validated")
# Logs: [order_id=12345] Order validated# [BAD] Repeating context manuallydefprocess_order(order_id: str):
logger.info(f"[order_id={order_id}] Processing order")
logger.info(f"[order_id={order_id}] Order validated") # Repetitive

Log Singleton Initialization in Factory Functions

Constraint: Factory functions creating singletons MUST log initialization at DEBUG level.

Rationale: Singleton initialization is a key diagnostic event for understanding application startup and dependency creation order. DEBUG level provides visibility during development without cluttering production logs.

Examples:

# [GOOD] - Log singleton initializationimportlogginglogger=logging.getLogger(__name__)
_client: AlertmanagerClient|None=Nonedefget_client() ->AlertmanagerClient:
"""Get or create the Alertmanager client singleton."""global_clientif_clientisNone:
logger.debug("Initializing Alertmanager client")
_client=AlertmanagerClient(get_config())
return_client# [BAD] - Silent initializationdefget_client() ->AlertmanagerClient:
global_clientif_clientisNone:
_client=AlertmanagerClient(get_config()) # No visibilityreturn_client

When to log:

• Singleton creation (first initialization)
• Database connection pool creation
• External client initialization (API, cache, queue)
• Configuration loading

Why DEBUG level:

• Not needed in production unless debugging startup issues
• Can be enabled via LOG_LEVEL=DEBUG when diagnosing problems
• Avoids noise in normal operation

Reference: alertmanager-mcp factory.py demonstrates factory logging pattern.

Multi-Handler Configuration for Different Outputs

Constraint: Applications requiring multiple outputs (console, file, error tracking) MUST use manual handler configuration, not basicConfig().

Rationale:basicConfig() only supports single handler/format, while manual setup enables per-destination configuration.

Examples:

# [GOOD] Multiple handlers with different configsfromlogging.handlersimportRotatingFileHandler# Console handler (INFO and above)console_handler=logging.StreamHandler()
console_handler.setLevel(logging.INFO)
console_handler.setFormatter(logging.Formatter('%(levelname)s: %(message)s'))
# File handler (DEBUG and above)file_handler=RotatingFileHandler(
'app.log',
maxBytes=10_000_000, # 10MBbackupCount=5
)
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(logging.Formatter(
'%(asctime)s %(levelname)-8s [%(filename)s:%(lineno)d] %(message)s'
))
# Configure root loggerlogging.root.setLevel(logging.DEBUG)
logging.root.addHandler(console_handler)
logging.root.addHandler(file_handler)
# [BAD] Trying to use basicConfig for multiple handlerslogging.basicConfig(level=logging.INFO) # Only creates one handler

Common Antipatterns

Never Use print() for Logging

Constraint: Code MUST use logging module, never print() for debugging or status output.

Rationale:print() lacks levels, timestamps, context, and cannot be configured or redirected.

Examples:

# [BAD] Using print()print(f"User {user_id} logged in")
# [GOOD] Using logginglogger.info(f"User login: user_id={user_id}")

Avoid Logging During Interpreter Shutdown

Constraint: Code that logs in cleanup/shutdown handlers MUST wrap logging in try/except to handle handler unavailability.

Rationale: Logging handlers may be destroyed before cleanup code runs, causing exceptions during shutdown.

Examples:

# [GOOD] Safe shutdown loggingimportatexitdefcleanup():
try:
logger.info("Cleanup started")
# ... cleanup codelogger.info("Cleanup completed")
exceptException:
pass# Logging may fail during shutdownatexit.register(cleanup)

Ensure UTF-8 Encoding for File Handlers

Constraint: File handlers MUST specify encoding='utf-8' when logging non-ASCII characters.

Rationale: Default encoding may vary by platform, causing Unicode errors with international characters.

Examples:

# [GOOD] UTF-8 file handlerfile_handler=logging.FileHandler('app.log', encoding='utf-8')
user_name="José García"logger.info(f"User registered: {user_name}") # Works correctly

Decision Framework

basicConfig vs Custom Configuration

Use basicConfig():

• Simple applications
• Single output destination
• Quick setup

Use custom handlers:

• Multiple outputs (console + file + error tracking)
• Different formats per destination
• Rotating log files
• Production systems

Module Logger vs Root Logger

Use module logger (__name__):

• Libraries and reusable components
• Want per-module control
• Multi-module applications

Use root logger (logging.info()):

• Simple scripts
• Single-file applications
• Quick prototypes

Related Documentation

• Project structure for logging_setup.py organization: python-project-structure.md
• CLI arguments for runtime log level control: python-cli-arguments-guide.md