diff --git a/docs/getting_started.rst b/docs/getting_started.rst index 67321024..a8303ce0 100644 --- a/docs/getting_started.rst +++ b/docs/getting_started.rst @@ -94,14 +94,106 @@ For Python, you can use the bootstrap list to connect to known peers: Debugging --------- -When running libp2p you may want to see what things are happening behind the scenes. You can enable debug logging by setting the appropriate log level: +When running libp2p you may want to see what things are happening behind the scenes. You can enable debug logging using the `LIBP2P_DEBUG` environment variable. This allows for fine-grained control over which modules log at which levels. -.. code:: python +Basic Usage +~~~~~~~~~~~ - import logging +To enable debug logging for all modules: - # Set debug level for libp2p - logging.getLogger('libp2p').setLevel(logging.DEBUG) +.. code:: bash + + # Method 1: Using export (persists for the shell session) + # On Unix-like systems (Linux, macOS): + export LIBP2P_DEBUG=DEBUG + # On Windows (Command Prompt): + set LIBP2P_DEBUG=DEBUG + # On Windows (PowerShell): + $env:LIBP2P_DEBUG="DEBUG" + + # Method 2: Setting for a single command + # On Unix-like systems: + LIBP2P_DEBUG=DEBUG python your_script.py + # On Windows (Command Prompt): + set LIBP2P_DEBUG=DEBUG && python your_script.py + # On Windows (PowerShell): + $env:LIBP2P_DEBUG="DEBUG"; python your_script.py + + # Method 3: Redirect logs to /dev/null to suppress console output + # On Unix-like systems: + LIBP2P_DEBUG=DEBUG python your_script.py 2>/dev/null + # On Windows (Command Prompt): + set LIBP2P_DEBUG=DEBUG && python your_script.py >nul 2>&1 + # On Windows (PowerShell): + $env:LIBP2P_DEBUG="DEBUG"; python your_script.py *> $null + +To enable debug logging for specific modules: + +.. code:: bash + + # Debug logging for identity module only + # On Unix-like systems: + export LIBP2P_DEBUG=identity.identify:DEBUG + # On Windows (Command Prompt): + set LIBP2P_DEBUG=identity.identify:DEBUG + # On Windows (PowerShell): + $env:LIBP2P_DEBUG="identity.identify:DEBUG" + + # Multiple modules with different levels + # On Unix-like systems: + export LIBP2P_DEBUG=identity.identify:DEBUG,transport:INFO + # On Windows (Command Prompt): + set LIBP2P_DEBUG=identity.identify:DEBUG,transport:INFO + # On Windows (PowerShell): + $env:LIBP2P_DEBUG="identity.identify:DEBUG,transport:INFO" + +Log Files +~~~~~~~~~ + +By default, logs are written to a file in the system's temporary directory with a timestamp and unique identifier. The file path is printed to stderr when logging starts. + +When no custom log file is specified: + - Logs are written to both a default file and to stderr (console output) + - The default file path is printed to stderr when logging starts + +When a custom log file is specified: + - Logs are written only to the specified file + - No console output is generated + +To specify a custom log file location: + +.. code:: bash + + # Method 1: Using export (persists for the shell session) + # On Unix-like systems: + export LIBP2P_DEBUG_FILE=/path/to/your/logfile.log + # On Windows (Command Prompt): + set LIBP2P_DEBUG_FILE=C:\path\to\your\logfile.log + # On Windows (PowerShell): + $env:LIBP2P_DEBUG_FILE="C:\path\to\your\logfile.log" + + # Method 2: Setting for a single command + # On Unix-like systems: + LIBP2P_DEBUG=DEBUG LIBP2P_DEBUG_FILE=/path/to/your/logfile.log python your_script.py + # On Windows (Command Prompt): + set LIBP2P_DEBUG=DEBUG && set LIBP2P_DEBUG_FILE=C:\path\to\your\logfile.log && python your_script.py + # On Windows (PowerShell): + $env:LIBP2P_DEBUG="DEBUG"; $env:LIBP2P_DEBUG_FILE="C:\path\to\your\logfile.log"; python your_script.py + +Log Format +~~~~~~~~~~ + +Log messages follow this format: + +.. code:: text + + timestamp - module_name - level - message + +Example output: + +.. code:: text + + 2024-01-01 12:00:00,123 - libp2p.identity.identify - DEBUG - Starting identify protocol What's Next ----------- diff --git a/docs/libp2p.rst b/docs/libp2p.rst index 8b1a8f08..b82676d1 100644 --- a/docs/libp2p.rst +++ b/docs/libp2p.rst @@ -19,6 +19,7 @@ Subpackages libp2p.stream_muxer libp2p.tools libp2p.transport + libp2p.utils Submodules ---------- diff --git a/docs/libp2p.utils.rst b/docs/libp2p.utils.rst new file mode 100644 index 00000000..d52fb251 --- /dev/null +++ b/docs/libp2p.utils.rst @@ -0,0 +1,29 @@ +libp2p.utils package +==================== + +Submodules +---------- + +libp2p.utils.logging module +--------------------------- + +.. automodule:: libp2p.utils.logging + :members: + :undoc-members: + :show-inheritance: + +libp2p.utils.varint module +-------------------------- + +.. automodule:: libp2p.utils.varint + :members: + :undoc-members: + :show-inheritance: + +libp2p.utils.version module +--------------------------- + +.. automodule:: libp2p.utils.version + :members: + :undoc-members: + :show-inheritance: diff --git a/libp2p/__init__.py b/libp2p/__init__.py index bc7e7510..f92f9399 100644 --- a/libp2p/__init__.py +++ b/libp2p/__init__.py @@ -47,6 +47,12 @@ from libp2p.transport.tcp.tcp import ( from libp2p.transport.upgrader import ( TransportUpgrader, ) +from libp2p.utils.logging import ( + setup_logging, +) + +# Initialize logging configuration +setup_logging() def generate_new_rsa_identity() -> KeyPair: diff --git a/libp2p/utils/__init__.py b/libp2p/utils/__init__.py new file mode 100644 index 00000000..3b015c6a --- /dev/null +++ b/libp2p/utils/__init__.py @@ -0,0 +1,23 @@ +"""Utility functions for libp2p.""" + +from libp2p.utils.varint import ( + decode_uvarint_from_stream, + encode_delim, + encode_uvarint, + encode_varint_prefixed, + read_delim, + read_varint_prefixed_bytes, +) +from libp2p.utils.version import ( + get_agent_version, +) + +__all__ = [ + "decode_uvarint_from_stream", + "encode_delim", + "encode_uvarint", + "encode_varint_prefixed", + "get_agent_version", + "read_delim", + "read_varint_prefixed_bytes", +] diff --git a/libp2p/utils/logging.py b/libp2p/utils/logging.py new file mode 100644 index 00000000..637d028d --- /dev/null +++ b/libp2p/utils/logging.py @@ -0,0 +1,217 @@ +import atexit +from datetime import ( + datetime, +) +import logging +import logging.handlers +import os +from pathlib import ( + Path, +) +import queue +import sys +import threading +from typing import ( + Any, + Optional, + Union, +) + +# Create a log queue +log_queue: "queue.Queue[Any]" = queue.Queue() + +# Store the current listener to stop it on exit +_current_listener: Optional[logging.handlers.QueueListener] = None + +# Event to track when the listener is ready +_listener_ready = threading.Event() + +# Default format for log messages +DEFAULT_LOG_FORMAT = "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + + +def _parse_debug_modules(debug_str: str) -> dict[str, int]: + """ + Parse the LIBP2P_DEBUG environment variable to determine module-specific log levels. + + Format examples: + - "DEBUG" # All modules at DEBUG level + - "libp2p.identity.identify:DEBUG" # Only identify module at DEBUG + - "identity.identify:DEBUG" # Same as above, libp2p prefix is optional + - "libp2p.identity:DEBUG,libp2p.transport:INFO" # Multiple modules + """ + module_levels: dict[str, int] = {} + + # Handle empty or whitespace-only string + if not debug_str or debug_str.isspace(): + return module_levels + + # If it's a plain log level without any colons, apply to all + if ":" not in debug_str and debug_str.upper() in logging._nameToLevel: + return {"": getattr(logging, debug_str.upper())} + + # Handle module-specific levels + for part in debug_str.split(","): + if ":" not in part: + continue + + module, level = part.split(":") + level = level.upper() + + if level not in logging._nameToLevel: + continue + + # Handle module name + module = module.strip() + # Remove libp2p prefix if present, it will be added back when creating logger + module = module.replace("libp2p.", "") + # Convert any remaining dots to ensure proper format + module = module.replace("/", ".").strip(".") + + module_levels[module] = getattr(logging, level) + + return module_levels + + +def setup_logging() -> None: + """ + Set up logging configuration based on environment variables. + + Environment Variables: + LIBP2P_DEBUG + Controls logging levels. Examples: + - "DEBUG" (all modules at DEBUG level) + - "libp2p.identity.identify:DEBUG" (only identify module at DEBUG) + - "identity.identify:DEBUG" (same as above, libp2p prefix optional) + - "libp2p.identity:DEBUG,libp2p.transport:INFO" (multiple modules) + + LIBP2P_DEBUG_FILE + If set, specifies the file path for log output. When this variable is set, + logs will only be written to the specified file. If not set, logs will be + written to both a default file (in the system's temp directory) and to + stderr (console output). + + The logging system uses Python's native hierarchical logging: + - Loggers are organized in a hierarchy using dots + (e.g., libp2p.identity.identify) + - Child loggers inherit their parent's level unless explicitly set + - The root libp2p logger controls the default level + """ + global _current_listener, _listener_ready + + # Reset the event + _listener_ready.clear() + + # Stop existing listener if any + if _current_listener is not None: + _current_listener.stop() + _current_listener = None + + # Get the log level from environment variable + debug_str = os.environ.get("LIBP2P_DEBUG", "") + + if not debug_str: + # If LIBP2P_DEBUG is not set, disable logging + root_logger = logging.getLogger("libp2p") + root_logger.handlers.clear() + root_logger.setLevel(logging.WARNING) + root_logger.propagate = False + _listener_ready.set() # Signal that we're done + return + + # Parse module-specific levels + module_levels = _parse_debug_modules(debug_str) + + # If no valid levels specified, default to WARNING + if not module_levels: + root_logger = logging.getLogger("libp2p") + root_logger.handlers.clear() + root_logger.setLevel(logging.WARNING) + root_logger.propagate = False + _listener_ready.set() # Signal that we're done + return + + # Create formatter + formatter = logging.Formatter(DEFAULT_LOG_FORMAT) + + # Configure handlers + handlers: list[Union[logging.StreamHandler[Any], logging.FileHandler]] = [] + + # Console handler + console_handler = logging.StreamHandler(sys.stderr) + console_handler.setFormatter(formatter) + handlers.append(console_handler) + + # File handler (if configured) + log_file = os.environ.get("LIBP2P_DEBUG_FILE") + + if log_file: + # Ensure the directory exists + log_path = Path(log_file) + log_path.parent.mkdir(parents=True, exist_ok=True) + else: + # Default log file with timestamp and unique identifier + timestamp = datetime.now().strftime("%Y%m%d_%H%M%S_%f") + unique_id = os.urandom(4).hex() # Add a unique identifier to prevent collisions + if os.name == "nt": # Windows + log_file = f"C:\\Windows\\Temp\\py-libp2p_{timestamp}_{unique_id}.log" + else: # Unix-like + log_file = f"/tmp/py-libp2p_{timestamp}_{unique_id}.log" + + # Print the log file path so users know where to find it + print(f"Logging to: {log_file}", file=sys.stderr) + + try: + file_handler = logging.FileHandler( + log_file, mode="w" + ) # Use 'w' mode to clear file + file_handler.setFormatter(formatter) + handlers.append(file_handler) + except Exception as e: + print(f"Error creating file handler: {e}", file=sys.stderr) + raise + + # Create a QueueHandler and QueueListener + queue_handler = logging.handlers.QueueHandler(log_queue) + + # Configure root logger for libp2p + root_logger = logging.getLogger("libp2p") + root_logger.handlers.clear() + root_logger.addHandler(queue_handler) + root_logger.propagate = False + + # Set default level based on configuration + if "" in module_levels: + # Global level specified + root_logger.setLevel(module_levels[""]) + else: + # Default to INFO for module-specific logging + root_logger.setLevel(logging.INFO) + + # Configure module-specific levels + for module, level in module_levels.items(): + if module: # Skip the default "" key + logger = logging.getLogger(f"libp2p.{module}") + logger.handlers.clear() + logger.addHandler(queue_handler) + logger.setLevel(level) + logger.propagate = False # Prevent message duplication + + # Start the listener AFTER configuring all loggers + _current_listener = logging.handlers.QueueListener( + log_queue, *handlers, respect_handler_level=True + ) + _current_listener.start() + + # Signal that the listener is ready + _listener_ready.set() + + +# Register cleanup function +@atexit.register +def cleanup_logging() -> None: + """Clean up logging resources on exit.""" + global _current_listener + if _current_listener is not None: + _current_listener.stop() + _current_listener = None diff --git a/libp2p/utils.py b/libp2p/utils/varint.py similarity index 80% rename from libp2p/utils.py rename to libp2p/utils/varint.py index b2c91eb5..b9fa6b9b 100644 --- a/libp2p/utils.py +++ b/libp2p/utils/varint.py @@ -1,6 +1,3 @@ -from importlib.metadata import ( - version, -) import itertools import logging import math @@ -11,12 +8,11 @@ from libp2p.exceptions import ( from libp2p.io.abc import ( Reader, ) - -from .io.utils import ( +from libp2p.io.utils import ( read_exactly, ) -logger = logging.getLogger("libp2p.utils") +logger = logging.getLogger("libp2p.utils.varint") # Unsigned LEB128(varint codec) # Reference: https://github.com/ethereum/py-wasm/blob/master/wasm/parsers/leb128.py @@ -24,7 +20,6 @@ logger = logging.getLogger("libp2p.utils") LOW_MASK = 2**7 - 1 HIGH_MASK = 2**7 - # The maximum shift width for a 64 bit integer. We shouldn't have to decode # integers larger than this. SHIFT_64_BIT_MAX = int(math.ceil(64 / 7)) * 7 @@ -90,19 +85,3 @@ async def read_delim(reader: Reader) -> bytes: f'`msg_bytes` is not delimited by b"\\n": `msg_bytes`={msg_bytes!r}' ) return msg_bytes[:-1] - - -def get_agent_version() -> str: - """ - Return the version of libp2p. - - If the version cannot be determined due to an exception, return "py-libp2p/unknown". - - :return: The version of libp2p. - :rtype: str - """ - try: - return f"py-libp2p/{version('libp2p')}" - except Exception as e: - logger.warning("Could not fetch libp2p version: %s", e) - return "py-libp2p/unknown" diff --git a/libp2p/utils/version.py b/libp2p/utils/version.py new file mode 100644 index 00000000..44cc98d2 --- /dev/null +++ b/libp2p/utils/version.py @@ -0,0 +1,22 @@ +from importlib.metadata import ( + version, +) +import logging + +logger = logging.getLogger("libp2p.utils.version") + + +def get_agent_version() -> str: + """ + Return the version of libp2p. + + If the version cannot be determined due to an exception, return "py-libp2p/unknown". + + :return: The version of libp2p. + :rtype: str + """ + try: + return f"py-libp2p/{version('libp2p')}" + except Exception as e: + logger.warning("Could not fetch libp2p version: %s", e) + return "py-libp2p/unknown" diff --git a/newsfragments/608.feature.rst b/newsfragments/608.feature.rst new file mode 100644 index 00000000..fd01e8cb --- /dev/null +++ b/newsfragments/608.feature.rst @@ -0,0 +1 @@ +Feature: Logging in py-libp2p via env vars diff --git a/tests/utils/__init__.py b/tests/utils/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/tests/utils/test_logging.py b/tests/utils/test_logging.py new file mode 100644 index 00000000..51dafb7f --- /dev/null +++ b/tests/utils/test_logging.py @@ -0,0 +1,257 @@ +import logging +import os +from pathlib import ( + Path, +) +import queue +import tempfile +import threading +from unittest.mock import ( + patch, +) + +import pytest +import trio + +from libp2p.utils.logging import ( + _current_listener, + _listener_ready, + log_queue, + setup_logging, +) + + +def _reset_logging(): + """Reset all logging state.""" + global _current_listener, _listener_ready + + # Stop existing listener if any + if _current_listener is not None: + _current_listener.stop() + _current_listener = None + + # Reset the event + _listener_ready = threading.Event() + + # Reset the root logger + root = logging.getLogger() + root.handlers.clear() + root.setLevel(logging.WARNING) + + # Clear all loggers + for name in list(logging.Logger.manager.loggerDict.keys()): + if name.startswith("libp2p"): + del logging.Logger.manager.loggerDict[name] # Remove logger from registry + + # Reset libp2p logger + logger = logging.getLogger("libp2p") + logger.handlers.clear() + logger.propagate = False # Don't propagate to Python's root logger + logger.setLevel(logging.WARNING) # Default level + + # Clear the log queue + while not log_queue.empty(): + try: + log_queue.get_nowait() + except queue.Empty: + break + + +@pytest.fixture(autouse=True) +def clean_env(): + """Remove relevant environment variables before each test.""" + # Save original environment + original_env = {} + for var in ["LIBP2P_DEBUG", "LIBP2P_DEBUG_FILE"]: + if var in os.environ: + original_env[var] = os.environ[var] + del os.environ[var] + + # Reset logging state + _reset_logging() + + yield + + # Reset logging state again + _reset_logging() + + # Restore original environment + for var, value in original_env.items(): + os.environ[var] = value + + +@pytest.fixture +def clean_logger(): + """Reset the libp2p logger before each test.""" + # Reset logging state + _reset_logging() + + yield logging.getLogger("libp2p") + + # Reset logging state again + _reset_logging() + + +def test_logging_disabled(clean_env): + """Test that logging is disabled when LIBP2P_DEBUG is not set.""" + setup_logging() + logger = logging.getLogger("libp2p") + assert logger.level == logging.WARNING + assert not logger.handlers + + +def test_logging_with_debug_env(clean_env): + """Test that logging is properly configured when LIBP2P_DEBUG is set.""" + os.environ["LIBP2P_DEBUG"] = "DEBUG" + setup_logging() + logger = logging.getLogger("libp2p") + + assert logger.level == logging.DEBUG + assert len(logger.handlers) == 1 # Should have the QueueHandler + + # The handler should be a QueueHandler + assert isinstance(logger.handlers[0], logging.handlers.QueueHandler) + + +def test_module_specific_logging(clean_env): + """Test module-specific logging levels.""" + os.environ["LIBP2P_DEBUG"] = "identity.identify:DEBUG,transport:INFO" + setup_logging() + + # Check root logger (should be at INFO by default) + root_logger = logging.getLogger("libp2p") + assert root_logger.level == logging.INFO + + # Check identify module (should be at DEBUG) + identify_logger = logging.getLogger("libp2p.identity.identify") + assert identify_logger.level == logging.DEBUG + + # Check transport module (should be at INFO) + transport_logger = logging.getLogger("libp2p.transport") + assert transport_logger.level == logging.INFO + + # Check unspecified module (should inherit from root) + other_logger = logging.getLogger("libp2p.other") + assert other_logger.getEffectiveLevel() == logging.INFO + + +def test_global_logging_level(clean_env): + """Test setting a global logging level.""" + os.environ["LIBP2P_DEBUG"] = "DEBUG" + setup_logging() + + # Root logger should be at DEBUG + root_logger = logging.getLogger("libp2p") + assert root_logger.level == logging.DEBUG + + # All modules should inherit the DEBUG level + for module in ["identity", "transport", "other"]: + logger = logging.getLogger(f"libp2p.{module}") + assert logger.getEffectiveLevel() == logging.DEBUG + + +@pytest.mark.trio +async def test_custom_log_file(clean_env): + """Test logging to a custom file path.""" + with tempfile.TemporaryDirectory() as temp_dir: + log_file = Path(temp_dir) / "test.log" + os.environ["LIBP2P_DEBUG"] = "INFO" + os.environ["LIBP2P_DEBUG_FILE"] = str(log_file) + + setup_logging() + + # Wait for the listener to be ready + _listener_ready.wait(timeout=1) + + logger = logging.getLogger("libp2p") + logger.info("Test message") + + # Give the listener time to process the message + await trio.sleep(0.1) + + # Stop the listener to ensure all messages are written + if _current_listener is not None: + _current_listener.stop() + + # Check if the file exists and contains our message + assert log_file.exists() + content = log_file.read_text() + assert "Test message" in content + + +@pytest.mark.trio +async def test_default_log_file(clean_env): + """Test logging to the default file path.""" + os.environ["LIBP2P_DEBUG"] = "INFO" + + with patch("libp2p.utils.logging.datetime") as mock_datetime: + # Mock the timestamp to have a predictable filename + mock_datetime.now.return_value.strftime.return_value = "20240101_120000" + + # Remove the log file if it exists + if os.name == "nt": # Windows + log_file = Path("C:/Windows/Temp/20240101_120000_py-libp2p.log") + else: # Unix-like + log_file = Path("/tmp/20240101_120000_py-libp2p.log") + log_file.unlink(missing_ok=True) + + setup_logging() + + # Wait for the listener to be ready + _listener_ready.wait(timeout=1) + + logger = logging.getLogger("libp2p") + logger.info("Test message") + + # Give the listener time to process the message + await trio.sleep(0.1) + + # Stop the listener to ensure all messages are written + if _current_listener is not None: + _current_listener.stop() + + # Check the default log file + if log_file.exists(): # Only check content if we have write permission + content = log_file.read_text() + assert "Test message" in content + + +def test_invalid_log_level(clean_env): + """Test handling of invalid log level in LIBP2P_DEBUG.""" + os.environ["LIBP2P_DEBUG"] = "INVALID_LEVEL" + setup_logging() + logger = logging.getLogger("libp2p") + + # Should default to WARNING when invalid level is provided + assert logger.level == logging.WARNING + + +def test_invalid_module_format(clean_env): + """Test handling of invalid module format in LIBP2P_DEBUG.""" + os.environ["LIBP2P_DEBUG"] = "identity.identify:DEBUG,invalid_format" + setup_logging() + + # The valid module should be configured + identify_logger = logging.getLogger("libp2p.identity.identify") + assert identify_logger.level == logging.DEBUG + + +def test_module_name_handling(clean_env): + """Test various module name formats.""" + # Test multiple formats in one go + os.environ["LIBP2P_DEBUG"] = ( + "identity.identify:DEBUG," # No libp2p prefix + "libp2p.transport:INFO," # With libp2p prefix + "pubsub/gossipsub:WARN" # Using slash instead of dot + ) + setup_logging() + + # Check each logger + identify_logger = logging.getLogger("libp2p.identity.identify") + assert identify_logger.level == logging.DEBUG + + transport_logger = logging.getLogger("libp2p.transport") + assert transport_logger.level == logging.INFO + + gossipsub_logger = logging.getLogger("libp2p.pubsub.gossipsub") + assert gossipsub_logger.level == logging.WARNING