Feat/issue 605 debug logging via env variable (#608)

* feat: Debug Logging via Environment Variable

* refactor: deleted libp2p/utils.py

* fix: double messages logging fix

* doc: add logging info to getting_started.rst

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
 -----------

docs/libp2p.rst

@@ -19,6 +19,7 @@ Subpackages
    libp2p.stream_muxer
    libp2p.tools
    libp2p.transport
+   libp2p.utils
 
 Submodules
 ----------

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:

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:

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",
+]

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

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"

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"

newsfragments/608.feature.rst

@@ -0,0 +1 @@
+Feature: Logging in py-libp2p via env vars

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