{ "cells": [ { "cell_type": "markdown", "metadata": {}, "source": [ "# Python Logging Tutorial\n", "\n", "This notebook provides a comprehensive guide to Python's logging module, covering basic concepts, advanced configurations, and best practices.\n", "\n", "## Table of Contents\n", "1. [Introduction to Logging](#introduction)\n", "2. [Basic Logging](#basic-logging)\n", "3. [Logging Levels](#logging-levels)\n", "4. [Configuring Loggers](#configuring-loggers)\n", "5. [Handlers and Formatters](#handlers-formatters)\n", "6. [Logging to Files](#logging-to-files)\n", "7. [Advanced Configuration](#advanced-configuration)\n", "8. [Best Practices](#best-practices)\n", "9. [Real-world Examples](#real-world-examples)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## 1. Introduction to Logging {#introduction}\n", "\n", "Logging is a means of tracking events that happen when software runs. It's essential for:\n", "- **Debugging**: Understanding what went wrong\n", "- **Monitoring**: Tracking application behavior\n", "- **Auditing**: Recording important events\n", "- **Performance**: Identifying bottlenecks\n", "\n", "Python's `logging` module provides a flexible framework for emitting log messages from Python programs." ] }, { "cell_type": "code", "execution_count": 1, "metadata": {}, "outputs": [], "source": [ "import logging\n", "import sys\n", "from datetime import datetime" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## 2. Basic Logging {#basic-logging}\n", "\n", "The simplest way to start logging is to use the module-level functions provided by the logging module." ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# Basic logging example\n", "logging.warning('This is a warning message')\n", "logging.error('This is an error message')\n", "logging.critical('This is a critical message')" ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# Why don't we see debug and info messages?\n", "logging.debug('This debug message will not appear')\n", "logging.info('This info message will not appear either')\n", "\n", "print(f\"Current logging level: {logging.getLogger().getEffectiveLevel()}\")\n", "print(f\"WARNING level value: {logging.WARNING}\")" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## 3. Logging Levels {#logging-levels}\n", "\n", "Python logging has five standard levels:\n", "\n", "| Level | Numeric Value | When to Use |\n", "|-------|---------------|-------------|\n", "| DEBUG | 10 | Detailed information for diagnosing problems |\n", "| INFO | 20 | General information about program execution |\n", "| WARNING | 30 | Something unexpected happened, but software still works |\n", "| ERROR | 40 | Serious problem occurred, software couldn't perform function |\n", "| CRITICAL | 50 | Very serious error, program may not continue |\n" ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# Configure basic logging to see all levels\n", "logging.basicConfig(level=logging.DEBUG, format='%(levelname)s: %(message)s')\n", "\n", "# Now all levels will be displayed\n", "logging.debug('Debug message - detailed diagnostic info')\n", "logging.info('Info message - general information')\n", "logging.warning('Warning message - something unexpected')\n", "logging.error('Error message - serious problem')\n", "logging.critical('Critical message - very serious error')" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## 4. Configuring Loggers {#configuring-loggers}\n", "\n", "For more control, create and configure your own logger instances." ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# Create a custom logger\n", "logger = logging.getLogger('my_app')\n", "logger.setLevel(logging.DEBUG)\n", "\n", "# Create console handler\n", "console_handler = logging.StreamHandler()\n", "console_handler.setLevel(logging.INFO)\n", "\n", "# Create formatter\n", "formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')\n", "console_handler.setFormatter(formatter)\n", "\n", "# Add handler to logger\n", "logger.addHandler(console_handler)\n", "\n", "# Test the logger\n", "logger.debug('This debug message will not appear (handler level is INFO)')\n", "logger.info('This info message will appear')\n", "logger.warning('This warning will appear')\n", "logger.error('This error will appear')" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## 5. Handlers and Formatters {#handlers-formatters}\n", "\n", "Handlers determine where log messages go, and formatters determine how they look." ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# Different formatter examples\n", "logger2 = logging.getLogger('formatted_logger')\n", "logger2.setLevel(logging.DEBUG)\n", "\n", "# Simple formatter\n", "simple_handler = logging.StreamHandler()\n", "simple_formatter = logging.Formatter('%(levelname)s: %(message)s')\n", "simple_handler.setFormatter(simple_formatter)\n", "\n", "# Detailed formatter\n", "detailed_handler = logging.StreamHandler()\n", "detailed_formatter = logging.Formatter(\n", " '%(asctime)s | %(name)s | %(levelname)-8s | %(filename)s:%(lineno)d | %(message)s'\n", ")\n", "detailed_handler.setFormatter(detailed_formatter)\n", "\n", "logger2.addHandler(simple_handler)\n", "logger2.info('Message with simple formatting')\n", "\n", "# Remove simple handler and add detailed handler\n", "logger2.removeHandler(simple_handler)\n", "logger2.addHandler(detailed_handler)\n", "logger2.info('Message with detailed formatting')" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "### Common Format Attributes\n", "\n", "| Attribute | Description |\n", "|-----------|-------------|\n", "| %(asctime)s | Human-readable time |\n", "| %(levelname)s | Log level name |\n", "| %(name)s | Logger name |\n", "| %(message)s | Log message |\n", "| %(filename)s | Filename |\n", "| %(lineno)d | Line number |\n", "| %(funcName)s | Function name |\n", "| %(process)d | Process ID |\n", "| %(thread)d | Thread ID |" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## 6. Logging to Files {#logging-to-files}\n", "\n", "File logging is crucial for production applications." ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# Create a file logger\n", "file_logger = logging.getLogger('file_logger')\n", "file_logger.setLevel(logging.DEBUG)\n", "\n", "# Create file handler\n", "file_handler = logging.FileHandler('app.log')\n", "file_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')\n", "file_handler.setFormatter(file_formatter)\n", "\n", "file_logger.addHandler(file_handler)\n", "\n", "# Log some messages\n", "file_logger.info('Application started')\n", "file_logger.warning('This is a warning')\n", "file_logger.error('An error occurred')\n", "\n", "print(\"Messages logged to 'app.log' file\")" ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# Rotating file handler to prevent log files from getting too large\n", "from logging.handlers import RotatingFileHandler\n", "\n", "rotating_logger = logging.getLogger('rotating_logger')\n", "rotating_logger.setLevel(logging.DEBUG)\n", "\n", "# Create rotating file handler (max 1MB, keep 3 backup files)\n", "rotating_handler = RotatingFileHandler(\n", " 'rotating_app.log', \n", " maxBytes=1024*1024, # 1MB\n", " backupCount=3\n", ")\n", "rotating_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')\n", "rotating_handler.setFormatter(rotating_formatter)\n", "\n", "rotating_logger.addHandler(rotating_handler)\n", "\n", "# Simulate some log entries\n", "for i in range(5):\n", " rotating_logger.info(f'Log entry number {i+1}')\n", "\n", "print(\"Messages logged to 'rotating_app.log' with rotation\")" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## 7. Advanced Configuration {#advanced-configuration}\n", "\n", "Use dictConfig for complex logging setups." ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "import logging.config\n", "\n", "# Advanced logging configuration using dictConfig\n", "LOGGING_CONFIG = {\n", " 'version': 1,\n", " 'disable_existing_loggers': False,\n", " 'formatters': {\n", " 'standard': {\n", " 'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'\n", " },\n", " 'detailed': {\n", " 'format': '%(asctime)s [%(levelname)s] %(name)s:%(lineno)d: %(message)s'\n", " }\n", " },\n", " 'handlers': {\n", " 'console': {\n", " 'level': 'INFO',\n", " 'class': 'logging.StreamHandler',\n", " 'formatter': 'standard',\n", " 'stream': 'ext://sys.stdout'\n", " },\n", " 'file': {\n", " 'level': 'DEBUG',\n", " 'class': 'logging.FileHandler',\n", " 'formatter': 'detailed',\n", " 'filename': 'advanced_app.log',\n", " 'mode': 'a'\n", " }\n", " },\n", " 'loggers': {\n", " 'my_app': {\n", " 'handlers': ['console', 'file'],\n", " 'level': 'DEBUG',\n", " 'propagate': False\n", " }\n", " },\n", " 'root': {\n", " 'level': 'WARNING',\n", " 'handlers': ['console']\n", " }\n", "}\n", "\n", "# Apply the configuration\n", "logging.config.dictConfig(LOGGING_CONFIG)\n", "\n", "# Get the configured logger\n", "advanced_logger = logging.getLogger('my_app')\n", "\n", "# Test the advanced logger\n", "advanced_logger.debug('Debug message - only in file')\n", "advanced_logger.info('Info message - in both console and file')\n", "advanced_logger.warning('Warning message')\n", "advanced_logger.error('Error message')" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## 8. Best Practices {#best-practices}\n", "\n", "Here are some logging best practices to follow:" ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# 1. Use appropriate log levels\n", "logger = logging.getLogger(__name__) # Use __name__ for logger names\n", "\n", "def process_user_data(user_id, data):\n", " \"\"\"Example function demonstrating good logging practices\"\"\"\n", " logger.info(f\"Processing data for user {user_id}\")\n", " \n", " try:\n", " # Simulate processing\n", " if not data:\n", " logger.warning(f\"No data provided for user {user_id}\")\n", " return None\n", " \n", " # Process data\n", " result = len(data) # Simple processing\n", " logger.debug(f\"Processed {result} items for user {user_id}\")\n", " \n", " return result\n", " \n", " except Exception as e:\n", " logger.error(f\"Error processing data for user {user_id}: {e}\", exc_info=True)\n", " raise\n", " \n", " finally:\n", " logger.info(f\"Finished processing for user {user_id}\")\n", "\n", "# Test the function\n", "process_user_data(123, ['item1', 'item2', 'item3'])\n", "process_user_data(456, [])" ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# 2. Use structured logging for better analysis\n", "import json\n", "\n", "class JSONFormatter(logging.Formatter):\n", " def format(self, record):\n", " log_entry = {\n", " 'timestamp': self.formatTime(record),\n", " 'level': record.levelname,\n", " 'logger': record.name,\n", " 'message': record.getMessage(),\n", " 'module': record.module,\n", " 'function': record.funcName,\n", " 'line': record.lineno\n", " }\n", " \n", " if record.exc_info:\n", " log_entry['exception'] = self.formatException(record.exc_info)\n", " \n", " return json.dumps(log_entry)\n", "\n", "# Create a logger with JSON formatting\n", "json_logger = logging.getLogger('json_logger')\n", "json_handler = logging.StreamHandler()\n", "json_handler.setFormatter(JSONFormatter())\n", "json_logger.addHandler(json_handler)\n", "json_logger.setLevel(logging.INFO)\n", "\n", "json_logger.info('User login successful')\n", "json_logger.warning('Login attempt from suspicious IP')" ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# 3. Use logging context managers for consistent formatting\n", "import contextlib\n", "from contextvars import ContextVar\n", "\n", "# Context variable for request ID\n", "request_id: ContextVar[str] = ContextVar('request_id', default='')\n", "\n", "class ContextualFormatter(logging.Formatter):\n", " def format(self, record):\n", " # Add request ID to the log record\n", " record.request_id = request_id.get()\n", " return super().format(record)\n", "\n", "# Set up contextual logger\n", "contextual_logger = logging.getLogger('contextual')\n", "contextual_handler = logging.StreamHandler()\n", "contextual_formatter = ContextualFormatter(\n", " '[%(request_id)s] %(asctime)s - %(levelname)s - %(message)s'\n", ")\n", "contextual_handler.setFormatter(contextual_formatter)\n", "contextual_logger.addHandler(contextual_handler)\n", "contextual_logger.setLevel(logging.INFO)\n", "\n", "@contextlib.contextmanager\n", "def request_context(req_id):\n", " \"\"\"Context manager to set request ID for logging\"\"\"\n", " token = request_id.set(req_id)\n", " try:\n", " yield\n", " finally:\n", " request_id.reset(token)\n", "\n", "# Use the contextual logger\n", "with request_context('REQ-001'):\n", " contextual_logger.info('Processing request')\n", " contextual_logger.warning('Request taking longer than expected')\n", "\n", "with request_context('REQ-002'):\n", " contextual_logger.info('Processing another request')\n", " contextual_logger.error('Request failed')" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## 9. Real-world Examples {#real-world-examples}\n", "\n", "Here are some practical examples of logging in real applications." ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# Example 1: Web API logging\n", "import time\n", "import uuid\n", "\n", "# Set up API logger\n", "api_logger = logging.getLogger('api')\n", "api_handler = logging.StreamHandler()\n", "api_formatter = logging.Formatter(\n", " '%(asctime)s - %(name)s - %(levelname)s - %(message)s'\n", ")\n", "api_handler.setFormatter(api_formatter)\n", "api_logger.addHandler(api_handler)\n", "api_logger.setLevel(logging.INFO)\n", "\n", "def api_endpoint(endpoint, user_id, request_data):\n", " \"\"\"Simulate an API endpoint with proper logging\"\"\"\n", " request_id = str(uuid.uuid4())[:8]\n", " start_time = time.time()\n", " \n", " api_logger.info(\n", " f\"[{request_id}] {endpoint} - User: {user_id} - Request started\"\n", " )\n", " \n", " try:\n", " # Simulate processing\n", " time.sleep(0.1) # Simulate work\n", " \n", " if 'error' in request_data:\n", " raise ValueError(\"Invalid request data\")\n", " \n", " # Simulate success\n", " response = {\"status\": \"success\", \"data\": \"processed\"}\n", " \n", " duration = time.time() - start_time\n", " api_logger.info(\n", " f\"[{request_id}] {endpoint} - User: {user_id} - \"\n", " f\"Request completed successfully in {duration:.3f}s\"\n", " )\n", " \n", " return response\n", " \n", " except Exception as e:\n", " duration = time.time() - start_time\n", " api_logger.error(\n", " f\"[{request_id}] {endpoint} - User: {user_id} - \"\n", " f\"Request failed in {duration:.3f}s: {e}\",\n", " exc_info=True\n", " )\n", " raise\n", "\n", "# Test the API endpoint\n", "api_endpoint('/users/profile', 'user123', {'name': 'John'})\n", "try:\n", " api_endpoint('/users/profile', 'user456', {'error': 'invalid'})\n", "except ValueError:\n", " pass # Expected error" ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# Example 2: Database operation logging\n", "db_logger = logging.getLogger('database')\n", "db_handler = logging.StreamHandler()\n", "db_formatter = logging.Formatter(\n", " '%(asctime)s - %(name)s - %(levelname)s - %(message)s'\n", ")\n", "db_handler.setFormatter(db_formatter)\n", "db_logger.addHandler(db_handler)\n", "db_logger.setLevel(logging.DEBUG)\n", "\n", "class DatabaseManager:\n", " def __init__(self):\n", " self.logger = logging.getLogger('database.manager')\n", " \n", " def connect(self):\n", " self.logger.info(\"Establishing database connection\")\n", " # Simulate connection\n", " time.sleep(0.05)\n", " self.logger.info(\"Database connection established\")\n", " \n", " def execute_query(self, query, params=None):\n", " query_id = str(uuid.uuid4())[:8]\n", " start_time = time.time()\n", " \n", " self.logger.debug(f\"[{query_id}] Executing query: {query}\")\n", " if params:\n", " self.logger.debug(f\"[{query_id}] Query parameters: {params}\")\n", " \n", " try:\n", " # Simulate query execution\n", " time.sleep(0.02)\n", " \n", " if 'DROP' in query.upper():\n", " raise Exception(\"DROP operations are not allowed\")\n", " \n", " duration = time.time() - start_time\n", " self.logger.info(\n", " f\"[{query_id}] Query executed successfully in {duration:.3f}s\"\n", " )\n", " \n", " return {\"rows\": 5, \"affected\": 1}\n", " \n", " except Exception as e:\n", " duration = time.time() - start_time\n", " self.logger.error(\n", " f\"[{query_id}] Query failed in {duration:.3f}s: {e}\"\n", " )\n", " raise\n", " \n", " def close(self):\n", " self.logger.info(\"Closing database connection\")\n", "\n", "# Test database operations\n", "db = DatabaseManager()\n", "db.connect()\n", "db.execute_query(\"SELECT * FROM users WHERE id = ?\", [123])\n", "db.execute_query(\"UPDATE users SET last_login = NOW() WHERE id = ?\", [123])\n", "\n", "try:\n", " db.execute_query(\"DROP TABLE users\")\n", "except Exception:\n", " pass # Expected error\n", " \n", "db.close()" ] }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], "source": [ "# Example 3: Application startup and shutdown logging\n", "app_logger = logging.getLogger('application')\n", "app_handler = logging.StreamHandler()\n", "app_formatter = logging.Formatter(\n", " '%(asctime)s - %(name)s - %(levelname)s - %(message)s'\n", ")\n", "app_handler.setFormatter(app_formatter)\n", "app_logger.addHandler(app_handler)\n", "app_logger.setLevel(logging.INFO)\n", "\n", "class Application:\n", " def __init__(self, name, version):\n", " self.name = name\n", " self.version = version\n", " self.logger = logging.getLogger(f'application.{name.lower()}')\n", " self.running = False\n", " \n", " def startup(self):\n", " \"\"\"Application startup with comprehensive logging\"\"\"\n", " self.logger.info(f\"Starting {self.name} v{self.version}\")\n", " \n", " try:\n", " # Log system information\n", " import platform\n", " self.logger.info(f\"Python version: {platform.python_version()}\")\n", " self.logger.info(f\"Platform: {platform.platform()}\")\n", " \n", " # Initialize components\n", " self.logger.info(\"Initializing components...\")\n", " \n", " components = ['Database', 'Cache', 'API Server', 'Background Tasks']\n", " for component in components:\n", " self.logger.info(f\"Initializing {component}...\")\n", " time.sleep(0.01) # Simulate initialization\n", " self.logger.info(f\"{component} initialized successfully\")\n", " \n", " self.running = True\n", " self.logger.info(f\"{self.name} started successfully\")\n", " \n", " except Exception as e:\n", " self.logger.critical(f\"Failed to start {self.name}: {e}\", exc_info=True)\n", " raise\n", " \n", " def shutdown(self):\n", " \"\"\"Application shutdown with proper cleanup logging\"\"\"\n", " self.logger.info(f\"Shutting down {self.name}...\")\n", " \n", " try:\n", " # Cleanup components in reverse order\n", " components = ['Background Tasks', 'API Server', 'Cache', 'Database']\n", " for component in components:\n", " self.logger.info(f\"Stopping {component}...\")\n", " time.sleep(0.01) # Simulate cleanup\n", " self.logger.info(f\"{component} stopped\")\n", " \n", " self.running = False\n", " self.logger.info(f\"{self.name} shutdown completed\")\n", " \n", " except Exception as e:\n", " self.logger.error(f\"Error during shutdown: {e}\", exc_info=True)\n", " \n", "# Test application lifecycle\n", "app = Application(\"MyWebApp\", \"1.2.3\")\n", "app.startup()\n", "time.sleep(0.1) # Simulate running\n", "app.shutdown()" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## Summary\n", "\n", "This notebook covered:\n", "\n", "1. **Basic logging concepts** and module-level functions\n", "2. **Logging levels** and when to use each one\n", "3. **Custom loggers** with handlers and formatters\n", "4. **File logging** with rotation capabilities\n", "5. **Advanced configuration** using dictConfig\n", "6. **Best practices** for production applications\n", "7. **Real-world examples** from web APIs, databases, and application lifecycle\n", "\n", "### Key Takeaways:\n", "\n", "- Use appropriate log levels for different types of information\n", "- Configure loggers with proper formatters for consistency\n", "- Use file handlers with rotation for production systems\n", "- Include context information (request IDs, user IDs) in log messages\n", "- Log both successful operations and errors with appropriate detail\n", "- Structure your logs for easy parsing and analysis\n", "- Use exc_info=True for exception logging to get stack traces\n", "\n", "Remember: Good logging is essential for maintaining and debugging applications in production!" ] } ], "metadata": { "kernelspec": { "display_name": "venv", "language": "python", "name": "python3" }, "language_info": { "codemirror_mode": { "name": "ipython", "version": 3 }, "file_extension": ".py", "mimetype": "text/x-python", "name": "python", "nbconvert_exporter": "python", "pygments_lexer": "ipython3", "version": "3.13.3" } }, "nbformat": 4, "nbformat_minor": 4 }