Log deserialization errors

[strawgate]

per #149 (comment)

we should setup loggers and write errors during silent errors like deserialization failures

perhaps debug logs for other actions?

[claude]

Claude finished @strawgate's task —— View job

---

Investigation Complete

tl;dr

Add logging to capture silent deserialization errors across the codebase. The most critical location is in PydanticAdapter._validate_model() where validation errors are silently suppressed when raise_on_validation_error=False (the default). Additional logging should be added to Elasticsearch batch operations and potentially to other stores that perform error recovery.

---

Recommendation

Implement structured logging for deserialization errors at two levels:

1. Error-level logs for actual deserialization failures (invalid data that can't be recovered)
2. Debug-level logs for normal operations (successful gets, puts, deletes, etc.)

The primary focus should be on logging silent errors - situations where the code currently catches exceptions and returns None without any indication that data corruption or validation issues occurred.

---

Findings

Current Silent Error Locations

1. PydanticAdapter (key-value-aio/src/key_value/aio/adapters/pydantic/adapter.py:73-77)

The most significant silent error location:

except ValidationError as e:
    if self._raise_on_validation_error:
        msg = f"Invalid Pydantic model: {value}"
        raise DeserializationError(msg) from e
    return None  # ⚠️ SILENT ERROR - no logging

Impact: When raise_on_validation_error=False (the default), Pydantic validation errors are completely silent. Users have no way to know their data failed validation unless they explicitly check for None returns.

Methods affected:

• get() - returns None instead of model
• get_many() - returns None for failed items in list
• ttl() - returns (None, None) hiding both value and TTL
• ttl_many() - returns (None, None) for failed items

2. Elasticsearch Batch Operations (mentioned in PR #149 discussion)

Per the PR #149 discussion at r2470091120, Elasticsearch's _get_managed_entries_many() was updated to catch DeserializationError per-document rather than failing the entire batch. However, there's no logging when this occurs (line 248):

entries_by_id[doc_id] = source_to_managed_entry(source=source)

This should be wrapped in try-except with logging when deserialization fails.

3. DataclassAdapter (similar pattern to PydanticAdapter)

Based on repository patterns, the DataclassAdapter likely has the same silent validation error behavior since it uses the same raise_on_validation_error flag.

Existing Logging Infrastructure

The project already has a LoggingWrapper (key-value-aio/src/key_value/aio/wrappers/logging/wrapper.py) that logs:

• Operation start/finish
• Hit/miss statistics
• Optional value logging (disabled by default for security)
• Structured logging support (JSON format)

However, this wrapper does not log internal errors like deserialization failures that occur deep in adapters/stores.

Detailed Action Plan

Phase 1: Add Logger Setup to Adapters and Stores

1. Add logger instances to classes that perform deserialization:

   • PydanticAdapter
   • DataclassAdapter
   • ElasticsearchStore
   • Any other stores with silent error handling

   import logging
   
   class PydanticAdapter:
       def __init__(self, ...):
           self._logger = logging.getLogger(f"key_value.adapters.pydantic")
           ...

2. Follow Python logging best practices:

   • Use module-level loggers (__name__)
   • Don't configure handlers (let application configure)
   • Use appropriate log levels (ERROR for failures, DEBUG for normal ops)

Phase 2: Add Error Logging to Silent Error Locations

PydanticAdapter._validate_model()

except ValidationError as e:
    if self._raise_on_validation_error:
        msg = f"Invalid Pydantic model: {value}"
        raise DeserializationError(msg) from e
    
    # NEW: Log the validation error
    self._logger.error(
        "Pydantic validation failed for value",
        extra={
            "error": str(e),
            "model": self._pydantic_model.__name__,
            "value_preview": str(value)[:200],  # Truncate for safety
        },
        exc_info=True  # Include traceback
    )
    return None

ElasticsearchStore._get_managed_entries_many()

Around line 248, wrap the deserialization call:

try:
    entries_by_id[doc_id] = source_to_managed_entry(source=source)
except DeserializationError as e:
    self._logger.error(
        "Failed to deserialize Elasticsearch document in batch operation",
        extra={
            "collection": collection,
            "document_id": doc_id,
            "error": str(e),
        },
        exc_info=True
    )
    entries_by_id[doc_id] = None

Phase 3: Add Debug Logging (Optional)

For normal operations, add DEBUG-level logs:

# In PydanticAdapter.get()
self._logger.debug(
    "Retrieved and validated model",
    extra={
        "key": key,
        "collection": collection,
        "model": self._pydantic_model.__name__,
    }
)

Phase 4: Documentation Updates

1. README.md: Document that applications should configure logging to capture deserialization errors:

   import logging
   logging.basicConfig(level=logging.ERROR)
   
   # Or configure specific logger
   logging.getLogger("key_value").setLevel(logging.ERROR)

2. Adapter docstrings: Update to mention logging behavior:

   """
   Args:
       raise_on_validation_error: Whether to raise DeserializationError on validation failures.
                                  If False, validation errors are logged at ERROR level and None is returned.
   """

Phase 5: Testing

1. Add tests that verify logging behavior:

   • Test that validation errors are logged when raise_on_validation_error=False
   • Test that logs include sufficient context (key, collection, error message)
   • Test that log level is ERROR for failures, DEBUG for normal ops

2. Use Python's logging.captureWarnings() in tests to verify log output

Implementation Order

1. Start with PydanticAdapter - highest impact, most users affected
2. Add to Elasticsearch store - addresses the specific PR feat: add native storage mode for Elasticsearch #149 issue
3. Add to DataclassAdapter - consistent with PydanticAdapter
4. Review other stores - look for similar silent error patterns
5. Add debug logging - lower priority, optional enhancement
6. Update documentation - ensure users know how to configure logging

Related Issues and Pull Requests

Repository	Item	Relevance
strawgate/py-key-value	PR #149	Direct trigger for this issue - discussion at r2470091120 identified need for logging deserialization errors in Elasticsearch batch operations
strawgate/py-key-value	PR #149 - discussion_r2470091120	CodeRabbit review comment suggesting error handling for batch deserialization, which prompted this issue
strawgate/py-key-value	Issue #137	In-depth review of AIO stores/wrappers - may have identified related error handling issues

Related Files

Repository	File	Relevance	Key Sections
strawgate/py-key-value	key-value-aio/src/key_value/aio/adapters/pydantic/adapter.py	Primary location of silent validation errors	73-77 - Silent error handling
strawgate/py-key-value	key-value-aio/src/key_value/aio/stores/elasticsearch/store.py	Batch operations mentioned in PR #149	248 - Batch deserialization
strawgate/py-key-value	key-value-aio/src/key_value/aio/wrappers/logging/wrapper.py	Existing logging infrastructure to reference	13-189 - LoggingWrapper implementation pattern
strawgate/py-key-value	key-value-shared/src/key_value/shared/errors/key_value.py	Error types to log	10-15 - SerializationError, DeserializationError

---

Problems Encountered During Investigation

None - all tools and resources were accessible and provided comprehensive information for the analysis.

---

[strawgate]

@claude please determine the best way for us to add logging here, let's look at other frameworks and make a PR for this.

[claude]

Claude finished @strawgate's task —— View job • claude/issue-154-20251028-1900 • Create PR ➔

---

Implementation Complete ✅

Tasks

• Read repository setup instructions (CLAUDE.md)
• Generate project summary
• Research logging patterns in popular Python frameworks
• Read existing adapter/store implementations
• Implement logging in BasePydanticAdapter._validate_model()
• Implement logging in ElasticsearchStore batch operations
• Add tests for logging behavior
• Run linting and type checking
• Commit and push changes
• Provide PR creation link

---

Implementation Summary

Changes Made:

1. BasePydanticAdapter (key-value-aio/src/key_value/aio/adapters/pydantic/base.py)

• Added logging import and module-level logger
• Added ERROR-level logging in _validate_model() when validation fails and raise_on_validation_error=False
• Logs include structured context using the extra parameter:
  • model_type: Type of model being validated
  • error_count: Number of validation errors
  • errors: Detailed error information from Pydantic
  • value_preview: Truncated preview of the value (200 chars max)
• Uses exc_info=True to include full traceback for debugging

2. ElasticsearchStore (key-value-aio/src/key_value/aio/stores/elasticsearch/store.py)

• Added logging import and module-level logger
• Wrapped source_to_managed_entry() in try-except in _get_managed_entries() batch operation
• Logs deserialization errors at ERROR level with context:
  • collection: The collection name
  • document_id: The document ID that failed
• Returns None for failed documents instead of failing the entire batch

3. Tests (key-value-aio/tests/adapters/test_pydantic.py)

• Added test_validation_error_logging(): Verifies logging when Pydantic validation fails
• Added test_list_validation_error_logging(): Verifies logging for list models with missing 'items' wrapper
• Tests use pytest's caplog fixture to capture and verify log records

---

Research Findings

Based on research of Django, Flask, SQLAlchemy, and Pydantic best practices:

Key Principles Applied:

1. ✅ Use standard Python logging module with module-level loggers (logging.getLogger(__name__))
2. ✅ Don't configure handlers in library code - let applications configure
3. ✅ Use appropriate log levels (ERROR for failures, DEBUG for normal ops)
4. ✅ Include context in log messages using structured logging (extra dict)
5. ✅ Use exc_info=True to include tracebacks for errors
6. ✅ Follow Python logging best practices for library code

---

Benefits

• Silent errors are now visible: Validation failures are logged at ERROR level
• Easy debugging: Structured logs include error details, value previews, and tracebacks
• Application control: Applications can configure logging to capture these errors
• Consistent behavior: Both PydanticAdapter and DataclassAdapter benefit from shared base class
• Machine-readable logs: Structured logging with extra dict enables log parsing and analysis
• Production-ready: All code passes linting (ruff) and type checking (basedpyright)

---

How to Use

Applications can now capture deserialization errors by configuring Python logging:

import logging

# Basic configuration
logging.basicConfig(level=logging.ERROR)

# Or configure specific logger
logging.getLogger("key_value.aio.adapters.pydantic").setLevel(logging.ERROR)
logging.getLogger("key_value.aio.stores.elasticsearch").setLevel(logging.ERROR)

# For JSON-formatted structured logs (production)
import json
import sys

class JSONFormatter(logging.Formatter):
    def format(self, record):
        log_data = {
            "timestamp": self.formatTime(record),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
        }
        # Include extra fields
        for key, value in record.__dict__.items():
            if key not in ["name", "msg", "args", "created", "filename", "funcName", 
                          "levelname", "levelno", "lineno", "module", "msecs", 
                          "message", "pathname", "process", "processName", 
                          "relativeCreated", "thread", "threadName", "exc_info", 
                          "exc_text", "stack_info"]:
                log_data[key] = value
        return json.dumps(log_data)

handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(JSONFormatter())
logging.getLogger("key_value").addHandler(handler)
logging.getLogger("key_value").setLevel(logging.ERROR)

---

|

[strawgate]

@claude let's make a pull request for this

[claude]

Claude finished @strawgate's task —— View job • claude/issue-154-20251028-1915

---

PR Ready ✅

Tasks

• Read repository setup instructions (CLAUDE.md)
• Generate project summary
• Check current branch status and existing changes
• Implement logging changes in BasePydanticAdapter
• Implement logging changes in ElasticsearchStore
• Add tests for logging behavior
• Run linting and type checking
• Commit and push changes
• Provide PR creation link

---

Summary

I've successfully implemented logging for deserialization errors as requested in issue #154:

Changes Made

1. BasePydanticAdapter (key-value-aio/src/key_value/aio/adapters/pydantic/base.py)

• Added logging import and module-level logger
• Added ERROR-level logging when Pydantic validation fails and raise_on_validation_error=False
• Logs include structured context: model type, error count, error details, value preview (truncated to 200 chars)
• Also logs when list models are missing the required 'items' wrapper
• Uses exc_info=True for validation errors to include full traceback

2. ElasticsearchStore (key-value-aio/src/key_value/aio/stores/elasticsearch/store.py)

• Added logging import and module-level logger
• Wrapped source_to_managed_entry() in try-except in _get_managed_entries() batch operation
• Logs deserialization errors at ERROR level with context: collection name, document ID
• Returns None for failed documents instead of failing the entire batch

3. Tests (key-value-aio/tests/adapters/test_pydantic.py)

• Added test_validation_error_logging(): Verifies logging when Pydantic validation fails
• Added test_list_validation_error_logging(): Verifies logging for list models with missing 'items' wrapper
• Tests use pytest's caplog fixture to capture and verify log records

Benefits

• Silent errors are now visible: Validation failures are logged at ERROR level
• Easy debugging: Structured logs include error details, value previews, and tracebacks
• Application control: Applications can configure Python logging to capture these errors
• Consistent behavior: Both PydanticAdapter and DataclassAdapter benefit from shared base class
• Production-ready: All code passes linting (ruff) and has correct syntax

How Applications Can Use This

import logging

# Basic configuration
logging.basicConfig(level=logging.ERROR)

# Or configure specific loggers
logging.getLogger("key_value.aio.adapters.pydantic").setLevel(logging.ERROR)
logging.getLogger("key_value.aio.stores.elasticsearch").setLevel(logging.ERROR)

---

Create PR

---

• claude/issue-154-20251028-1915