Enhanced Logging with Millisecond Precision and Robust Testing #728

.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

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,16 +197,28 @@ 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:
 
 ```toml
 [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.
 
 ---
 

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,24 +263,32 @@ 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
 
         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)