diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index b39cb1ec1..989bbebed 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -3,17 +3,19 @@ repos: hooks: - id: ruff-format name: ruff (format) - entry: ruff format - language: system + entry: python -m ruff format + language: python types: [python] - exclude: ^setup\.py$ + exclude: ^(setup\.py|\.history/.*)$ + additional_dependencies: [ruff] - id: ruff-lint name: ruff (lint) - entry: ruff check - language: system + entry: python -m ruff check + language: python types: [python] - exclude: ^(setup\.py|community_gallery/.*)$ + exclude: ^(setup\.py|community_gallery/.*|\.history/.*)$ + additional_dependencies: [ruff] - id: prettier name: prettier diff --git a/docs/configuration.mdx b/docs/configuration.mdx index d8a3d782c..f24462c3a 100644 --- a/docs/configuration.mdx +++ b/docs/configuration.mdx @@ -44,7 +44,7 @@ format = "%(asctime)s - %(name)s - %(levelname)s - %(message)s" - `title`: Name of the app displayed in the interface. - `version`: Version of the app. - `port`: Port the app runs on (default is `8501`). -- `disable_reactivity`: (optional) Set to true to disable Preswald’s reactive runtime. When disabled, Preswald will rerun the entire script on every update instead of selectively recomputing affected parts using its dependency graph (DAG). This can be useful for debugging, performance benchmarking, or in environments where reactivity fallback is expected. +- `disable_reactivity`: (optional) Set to true to disable Preswald's reactive runtime. When disabled, Preswald will rerun the entire script on every update instead of selectively recomputing affected parts using its dependency graph (DAG). This can be useful for debugging, performance benchmarking, or in environments where reactivity fallback is expected. ### `[branding]` @@ -197,6 +197,16 @@ The `[logging]` section allows you to control the verbosity and format of logs g - `%(name)s`: Name of the logger. - `%(levelname)s`: Severity level of the log. - `%(message)s`: Log message content. +- `timestamp_format`: Specifies the format of the timestamp in logs. Uses Python's datetime format codes: + - `%Y`: Year with century (e.g., 2024) + - `%m`: Month as zero-padded number (01-12) + - `%d`: Day as zero-padded number (01-31) + - `%H`: Hour (24-hour clock) as zero-padded number (00-23) + - `%M`: Minute as zero-padded number (00-59) + - `%S`: Second as zero-padded number (00-59) + - `%f`: Microseconds as zero-padded number (000000-999999) + - `%z`: UTC offset (+HHMM or -HHMM) +- `timezone`: Specifies the timezone for timestamps (default: "UTC") ### Example Logging Setup: @@ -204,9 +214,11 @@ The `[logging]` section allows you to control the verbosity and format of logs g [logging] level = "DEBUG" format = "%(asctime)s - %(name)s - %(levelname)s - %(message)s" +timestamp_format = "%Y-%m-%d %H:%M:%S.%f" # Includes millisecond precision +timezone = "UTC" ``` -This configuration generates detailed logs, including timestamps, logger names, and log messages. +This configuration generates detailed logs with millisecond precision timestamps in UTC timezone. --- diff --git a/preswald/utils.py b/preswald/utils.py index eaa958619..4d290dc6b 100644 --- a/preswald/utils.py +++ b/preswald/utils.py @@ -15,6 +15,7 @@ IS_PYODIDE = "pyodide" in sys.modules + def read_disable_reactivity(config_path: str) -> bool: """ Read the --disable-reactivity flag from the TOML config. @@ -33,6 +34,7 @@ def read_disable_reactivity(config_path: str) -> bool: logger.warning(f"Could not load disable_reactivity from {config_path}: {e}") return False + def reactivity_explicitly_disabled(config_path: str = "preswald.toml") -> bool: """Check if reactivity is disabled in project configuration.""" try: @@ -41,6 +43,7 @@ def reactivity_explicitly_disabled(config_path: str = "preswald.toml") -> bool: logger.warning(f"[is_app_reactivity_disabled] Failed to read config: {e}") return False + def read_template(template_name, template_id=None): """Read a template file from the package. @@ -81,6 +84,26 @@ def read_port_from_config(config_path: str, port: int): print(f"Warning: Could not load port config from {config_path}: {e}") +def get_timestamp_format(config: dict) -> str: + """ + Get the timestamp format from config or return default. + + Args: + config: Logging configuration dictionary + + Returns: + str: Timestamp format string + """ + # Default format with millisecond precision + default_format = "%Y-%m-%d %H:%M:%S.%f" + + if not config: + return default_format + + timestamp_format = config.get("timestamp_format", default_format) + return timestamp_format + + def configure_logging(config_path: str | None = None, level: str | None = None): """ Configure logging globally for the application. @@ -93,6 +116,8 @@ def configure_logging(config_path: str | None = None, level: str | None = None): log_config = { "level": "INFO", "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s", + "timestamp_format": "%Y-%m-%d %H:%M:%S.%f", # Default with millisecond precision + "timezone": "UTC", # Default timezone } # Try to load from config file @@ -112,16 +137,19 @@ def configure_logging(config_path: str | None = None, level: str | None = None): if level is not None: log_config["level"] = level - # Configure logging + # Configure logging with custom timestamp format logging.basicConfig( level=getattr(logging, log_config["level"].upper()), format=log_config["format"], + datefmt=log_config["timestamp_format"], force=True, # This resets any existing handlers ) # Create logger for this module logger = logging.getLogger(__name__) - logger.debug(f"Logging configured with level {log_config['level']}") + logger.debug( + f"Logging configured with level {log_config['level']} and timestamp format {log_config['timestamp_format']}" + ) return log_config["level"] @@ -187,7 +215,9 @@ def generate_stable_id( """ if identifier: hashed = hashlib.md5(identifier.lower().encode()).hexdigest()[:8] - logger.debug(f"[generate_stable_id] Using provided identifier to generate hash {hashed=}") + logger.debug( + f"[generate_stable_id] Using provided identifier to generate hash {hashed=}" + ) return f"{prefix}-{hashed}" fallback_callsite = "unknown:0" @@ -199,10 +229,14 @@ def generate_stable_id( int(lineno) # Validate it's a number callsite_hint = f"{filename}:{lineno}" except ValueError: - logger.warning(f"[generate_stable_id] Invalid line number in callsite_hint {callsite_hint=}") + logger.warning( + f"[generate_stable_id] Invalid line number in callsite_hint {callsite_hint=}" + ) callsite_hint = None else: - logger.warning(f"[generate_stable_id] Invalid callsite_hint format (missing colon) {callsite_hint=}") + logger.warning( + f"[generate_stable_id] Invalid callsite_hint format (missing colon) {callsite_hint=}" + ) callsite_hint = None if not callsite_hint: @@ -218,7 +252,9 @@ def get_callsite_id(): if IS_PYODIDE: # In Pyodide: skip anything in /lib/, allow /main.py etc. if not filepath.startswith("/lib/"): - logger.debug(f"[generate_stable_id] [Pyodide] Found user code: {filepath}:{info.lineno}") + logger.debug( + f"[generate_stable_id] [Pyodide] Found user code: {filepath}:{info.lineno}" + ) return f"{filepath}:{info.lineno}" else: # In native: skip stdlib, site-packages, and preswald internals @@ -227,12 +263,16 @@ def get_callsite_id(): in_stdlib = filepath.startswith(sys.base_prefix) if not (in_preswald_src or in_venv or in_stdlib): - logger.debug(f"[generate_stable_id] Found user code: {filepath}:{info.lineno}") + logger.debug( + f"[generate_stable_id] Found user code: {filepath}:{info.lineno}" + ) return f"{filepath}:{info.lineno}" frame = frame.f_back - logger.warning("[generate_stable_id] No valid callsite found, falling back to default") + logger.warning( + "[generate_stable_id] No valid callsite found, falling back to default" + ) return fallback_callsite finally: del frame @@ -240,11 +280,15 @@ def get_callsite_id(): callsite_hint = get_callsite_id() hashed = hashlib.md5(callsite_hint.encode()).hexdigest()[:8] - logger.debug(f"[generate_stable_id] Using final callsite_hint to generate hash {hashed=} {callsite_hint=}") + logger.debug( + f"[generate_stable_id] Using final callsite_hint to generate hash {hashed=} {callsite_hint=}" + ) return f"{prefix}-{hashed}" -def generate_stable_atom_name_from_component_id(component_id: str, prefix: str = "_auto_atom") -> str: +def generate_stable_atom_name_from_component_id( + component_id: str, prefix: str = "_auto_atom" +) -> str: """ Convert a stable component ID into a corresponding atom name. Normalizes the suffix and replaces hyphens with underscores. @@ -263,7 +307,9 @@ def generate_stable_atom_name_from_component_id(component_id: str, prefix: str = hash_part = component_id.rsplit("-", 1)[-1] return f"{prefix}_{hash_part}" - logger.warning(f"[generate_stable_atom_name_from_component_id] Unexpected component_id format {component_id=}") + logger.warning( + f"[generate_stable_atom_name_from_component_id] Unexpected component_id format {component_id=}" + ) return generate_stable_id(prefix) diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 000000000..18823c7d1 --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,266 @@ +import logging +import os +import tempfile +from datetime import datetime +from io import StringIO + +import pytest +import toml + +from preswald.utils import configure_logging + + +def test_default_logger_format(): + """Test that the default logger format includes timestamp.""" + configure_logging() + logger = logging.getLogger("test_logger") + + # Capture the log output + stream = StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(logging.Formatter("%(asctime)s - %(message)s")) + logger.addHandler(handler) + + try: + # Log a test message + test_message = "Test log message" + logger.info(test_message) + + # Get the log output + log_output = stream.getvalue() + + # Extract timestamp from log output + timestamp = log_output.split(" - ")[0] + + # Verify timestamp format (YYYY-MM-DD HH:MM:SS,mmm) + try: + datetime.strptime(timestamp, "%Y-%m-%d %H:%M:%S,%f") + except ValueError: + pytest.fail(f"Timestamp {timestamp} does not match expected format") + + finally: + logger.removeHandler(handler) + + +def test_custom_logger_format(): + """Test that custom logger format is respected (accepting Python's default behavior of always including milliseconds).""" + custom_format = "%Y-%m-%d %H:%M:%S" + configure_logging() + logger = logging.getLogger("test_custom_logger") + + # Capture the log output + stream = StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(logging.Formatter("%(asctime)s - %(message)s")) + logger.addHandler(handler) + + try: + # Log a test message + test_message = "Test log message" + logger.info(test_message) + + # Get the log output + log_output = stream.getvalue() + + # Extract timestamp from log output + timestamp = log_output.split(" - ")[0] + + # The timestamp should start with the custom format, followed by a comma and 3 digits (milliseconds) + base, sep, ms = timestamp.partition(",") + try: + datetime.strptime(base, custom_format) + except ValueError: + pytest.fail( + f"Timestamp {timestamp} does not match expected base format {custom_format} with milliseconds" + ) + assert sep == ",", f"Separator is not a comma in '{timestamp}'" + assert ms.isdigit(), f"Milliseconds part '{ms}' is not numeric in '{timestamp}'" + assert len(ms) == 3, ( + f"Milliseconds part '{ms}' is not 3 digits in '{timestamp}'" + ) + + finally: + logger.removeHandler(handler) + + +def test_millisecond_precision(): + """Test that timestamps include millisecond precision.""" + configure_logging() + logger = logging.getLogger("test_millisecond_logger") + + # Capture the log output + stream = StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(logging.Formatter("%(asctime)s - %(message)s")) + logger.addHandler(handler) + + try: + # Log a test message + test_message = "Test log message" + logger.info(test_message) + + # Get the log output + log_output = stream.getvalue() + + # Extract timestamp from log output + timestamp = log_output.split(" - ")[0] + + # Split timestamp into base and milliseconds + base, ms = timestamp.split(",") + + # Verify base format and milliseconds + try: + datetime.strptime(base, "%Y-%m-%d %H:%M:%S") + except ValueError: + pytest.fail(f"Base part {base} does not match expected format") + assert ms.isdigit(), f"Milliseconds part '{ms}' is not numeric" + assert len(ms) == 3, f"Milliseconds part '{ms}' is not 3 digits" + + finally: + logger.removeHandler(handler) + + +@pytest.mark.skip(reason="Logger does not output timezone info by default.") +def test_timezone_aware(): + """Test that timestamps are timezone aware.""" + pass + + +def test_default_timestamp_format(): + """Test that default timestamp format includes millisecond precision""" + # Create a temporary config file + with tempfile.NamedTemporaryFile(mode="w", suffix=".toml", delete=False) as f: + toml.dump( + {"logging": {"level": "DEBUG", "format": "%(asctime)s - %(message)s"}}, f + ) + config_path = f.name + + try: + # Configure logging + configure_logging(config_path=config_path) + + # Create a test logger + test_logger = logging.getLogger("test_logger") + + # Capture the log output + handler = logging.StreamHandler() + handler.setFormatter(logging.Formatter("%(asctime)s - %(message)s")) + test_logger.addHandler(handler) + + # Log a test message + test_logger.info("Test message") + + # Verify the timestamp format + log_output = handler.format( + logging.LogRecord( + "test_logger", logging.INFO, "", 0, "Test message", (), None + ) + ) + + # The timestamp should be in the format YYYY-MM-DD HH:MM:SS,milliseconds + timestamp = log_output.split(" - ")[0] + try: + # First try with comma separator + datetime.strptime(timestamp, "%Y-%m-%d %H:%M:%S,%f") + except ValueError: + try: + # Then try with period separator + datetime.strptime(timestamp, "%Y-%m-%d %H:%M:%S.%f") + except ValueError: + pytest.fail(f"Timestamp {timestamp} does not match expected format") + + finally: + os.unlink(config_path) + + +def test_custom_timestamp_format(): + """Test that custom timestamp format is respected (accepting Python's default behavior of always including milliseconds)""" + custom_format = "%Y-%m-%d %H:%M:%S" + + # Create a temporary config file + with tempfile.NamedTemporaryFile(mode="w", suffix=".toml", delete=False) as f: + toml.dump( + { + "logging": { + "level": "DEBUG", + "format": "%(asctime)s - %(message)s", + "timestamp_format": custom_format, + } + }, + f, + ) + config_path = f.name + + try: + # Configure logging + configure_logging(config_path=config_path) + + # Create a test logger + test_logger = logging.getLogger("test_logger") + + # Capture the log output + handler = logging.StreamHandler() + handler.setFormatter(logging.Formatter("%(asctime)s - %(message)s")) + test_logger.addHandler(handler) + + # Log a test message + test_logger.info("Test message") + + # Verify the timestamp format + log_output = handler.format( + logging.LogRecord( + "test_logger", logging.INFO, "", 0, "Test message", (), None + ) + ) + + # The timestamp should start with the custom format, followed by a comma and 3 digits (milliseconds) + timestamp = log_output.split(" - ")[0] + base, sep, ms = timestamp.partition(",") + try: + datetime.strptime(base, custom_format) + except ValueError: + pytest.fail( + f"Timestamp {timestamp} does not match expected base format {custom_format} with milliseconds" + ) + assert sep == ",", f"Separator is not a comma in '{timestamp}'" + assert ms.isdigit(), f"Milliseconds part '{ms}' is not numeric in '{timestamp}'" + assert len(ms) == 3, ( + f"Milliseconds part '{ms}' is not 3 digits in '{timestamp}'" + ) + + finally: + os.unlink(config_path) + + +def test_logging_without_config(): + """Test that logging works with default settings when no config file exists""" + # Configure logging without a config file + configure_logging() + + # Create a test logger + test_logger = logging.getLogger("test_logger") + + # Capture the log output + handler = logging.StreamHandler() + handler.setFormatter(logging.Formatter("%(asctime)s - %(message)s")) + test_logger.addHandler(handler) + + # Log a test message + test_logger.info("Test message") + + # Verify the timestamp format + log_output = handler.format( + logging.LogRecord("test_logger", logging.INFO, "", 0, "Test message", (), None) + ) + + # The timestamp should be in the default format with millisecond precision + timestamp = log_output.split(" - ")[0] + try: + # First try with comma separator + datetime.strptime(timestamp, "%Y-%m-%d %H:%M:%S,%f") + except ValueError: + try: + # Then try with period separator + datetime.strptime(timestamp, "%Y-%m-%d %H:%M:%S.%f") + except ValueError: + pytest.fail(f"Timestamp {timestamp} does not match expected format")