1
Fork 0
crypto_bot_training/Session_02/logging_examples.ipynb
2025-06-13 20:00:45 +02:00

749 lines
25 KiB
Text

{
"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
}