diff --git a/docs/getting-started/basic-usage.md b/docs/getting-started/basic-usage.md index 9f6265ec..209f33b9 100644 --- a/docs/getting-started/basic-usage.md +++ b/docs/getting-started/basic-usage.md @@ -200,3 +200,21 @@ for fact in facts: 2. Vector similarity search across fact embeddings 3. Results ranked by cosine similarity 4. Returns top N most relevant facts + +## Debug Logging + +Enable debug logging to see what Memori is doing internally: + +```python +import logging + +# Enable BEFORE importing Memori +logging.basicConfig(level=logging.DEBUG) + +from memori import Memori + +# Optional: show full content instead of truncated +memori = Memori(conn, debug_truncate=False) +``` + +See [Troubleshooting > Debug Logging](../troubleshooting.md#debug-logging) for more details. diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index 41af8646..ac0ad4af 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -14,6 +14,7 @@ This guide covers the most common issues developers face when using Memori and h 6. [API and Network Issues](#api-and-network-issues) 7. [LLM Integration Problems](#llm-integration-problems) 8. [Performance Issues](#performance-issues) +9. [Debug Logging](#debug-logging) --- @@ -677,6 +678,73 @@ except Exception as e: --- +## Debug Logging + +Enable debug logging to see exactly what Memori is doing internally. + +### Enable Debug Logging + +```python +import logging + +# Enable BEFORE importing Memori +logging.basicConfig( + level=logging.DEBUG, + format="%(asctime)s | %(name)s | %(levelname)s | %(message)s", +) + +from memori import Memori +``` + +### What You'll See + +``` +DEBUG | memori.memory.recall - Recall started - query: "What's my favorite..." (25 chars) +DEBUG | memori.llm._embeddings - Generating embedding using model: all-mpnet-base-v2 +DEBUG | memori._search - Retrieved 156 embeddings from database +DEBUG | memori._search - FAISS similarity search complete - top 5 matches: [0.92, 0.87, 0.84] +DEBUG | memori.llm._invoke - Sending request to LLM - provider: openai, model: gpt-4o-mini +DEBUG | memori.llm._base - LLM response received - latency: 1.23s +DEBUG | memori.memory._writer - Transaction committed - conversation_id: 42 +DEBUG | memori.memory.augmentation._manager - AA enqueued - scheduling augmentation +``` + +### Control Log Truncation + +By default, long content is truncated in logs for readability: + +```python +# Default: truncate long content (recommended) +memori = Memori(conn) + +# Show full content (for deep debugging) +memori = Memori(conn, debug_truncate=False) +``` + +### Filter Logs by Module + +```python +import logging + +# Only show specific module logs +logging.getLogger("memori.memory.recall").setLevel(logging.DEBUG) +logging.getLogger("memori.llm").setLevel(logging.DEBUG) + +# Silence other memori logs +logging.getLogger("memori").setLevel(logging.WARNING) +``` + +### Production Logging + +```python +import logging + +# Production: only show warnings and errors +logging.getLogger("memori").setLevel(logging.WARNING) +``` + +--- + ## Getting Help If you are still having issues after trying these solutions: diff --git a/memori/__init__.py b/memori/__init__.py index 3b15f627..7de822c5 100644 --- a/memori/__init__.py +++ b/memori/__init__.py @@ -69,11 +69,19 @@ def register( class Memori: - def __init__(self, conn: Callable[[], Any] | Any | None = None): + def __init__( + self, + conn: Callable[[], Any] | Any | None = None, + debug_truncate: bool = True, + ): + from memori._logging import set_truncate_enabled + self.config = Config() self.config.api_key = os.environ.get("MEMORI_API_KEY", None) self.config.enterprise = os.environ.get("MEMORI_ENTERPRISE", "0") == "1" self.config.session_id = uuid4() + self.config.debug_truncate = debug_truncate + set_truncate_enabled(debug_truncate) if conn is None: conn = self._get_default_connection() diff --git a/memori/_config.py b/memori/_config.py index c41fac41..4cae5f90 100644 --- a/memori/_config.py +++ b/memori/_config.py @@ -37,6 +37,7 @@ def __init__(self): self.api_key = None self.augmentation = None self.cache = Cache() + self.debug_truncate = True # Truncate long content in debug logs self.embeddings = Embeddings() self.enterprise = False self.llm = Llm() diff --git a/memori/_logging.py b/memori/_logging.py new file mode 100644 index 00000000..953ca431 --- /dev/null +++ b/memori/_logging.py @@ -0,0 +1,67 @@ +r""" + __ __ _ +| \/ | ___ _ __ ___ ___ _ __(_) +| |\/| |/ _ \ '_ ` _ \ / _ \| '__| | +| | | | __/ | | | | | (_) | | | | +|_| |_|\___|_| |_| |_|\___/|_| |_| + perfectam memoriam + memorilabs.ai +""" + +import copy +import logging + +logger = logging.getLogger(__name__) + +# Global setting for truncation (controlled by Config.debug_truncate) +_truncate_enabled = True + + +def set_truncate_enabled(enabled: bool) -> None: + """Set whether truncation is enabled for debug logs.""" + global _truncate_enabled + _truncate_enabled = enabled + logger.debug("Debug truncation %s", "enabled" if enabled else "disabled") + + +def truncate(text: str, max_len: int = 200) -> str: + """Truncate text for debug logging. + + Respects the global _truncate_enabled setting. When disabled, + returns the full text regardless of length. + + Args: + text: The text to truncate. + max_len: Maximum length before truncation (default: 200). + + Returns: + Original text if truncation disabled or under max_len, + otherwise truncated with '...' + """ + if not text: + return text + if not _truncate_enabled: + return text + if len(text) <= max_len: + return text + return text[:max_len] + "..." + + +def sanitize_payload(payload: dict) -> dict: + """Sanitize payload for safe logging by masking sensitive data. + + Removes or masks: + - API keys + - Authorization tokens + + Args: + payload: The payload dictionary to sanitize. + + Returns: + A deep copy of the payload with sensitive data masked. + """ + sanitized = copy.deepcopy(payload) + if "meta" in sanitized and "api" in sanitized["meta"]: + if sanitized["meta"]["api"].get("key"): + sanitized["meta"]["api"]["key"] = "***REDACTED***" + return sanitized diff --git a/memori/_network.py b/memori/_network.py index 3bbdf5a3..ab8d86d9 100644 --- a/memori/_network.py +++ b/memori/_network.py @@ -9,6 +9,7 @@ """ import asyncio +import logging import os import ssl @@ -27,6 +28,8 @@ QuotaExceededError, ) +logger = logging.getLogger(__name__) + class Api: def __init__(self, config: Config): @@ -53,6 +56,7 @@ async def augmentation_async(self, payload: dict) -> dict: url = self.url("sdk/augmentation") headers = self.headers() ssl_context = ssl.create_default_context(cafile=certifi.where()) + logger.debug("Sending augmentation request to %s", url) def _default_client_error_message(status_code: int) -> str: if status_code == 422: @@ -88,7 +92,10 @@ async def _read_error_payload(response: aiohttp.ClientResponse): json=payload, timeout=aiohttp.ClientTimeout(total=30), ) as r: + logger.debug("Augmentation response - status: %d", r.status) + if r.status == 429: + logger.warning("Rate limit exceeded (429)") if self._is_anonymous(): message, _data = await _read_error_payload(r) @@ -100,6 +107,7 @@ async def _read_error_payload(response: aiohttp.ClientResponse): if r.status == 422: message, data = await _read_error_payload(r) + logger.error("Validation error (422): %s", message) raise MemoriApiValidationError( status_code=422, message=message or _default_client_error_message(422), @@ -108,6 +116,7 @@ async def _read_error_payload(response: aiohttp.ClientResponse): if r.status == 433: message, data = await _read_error_payload(r) + logger.error("Request rejected (433): %s", message) raise MemoriApiRequestRejectedError( status_code=433, message=message or _default_client_error_message(433), @@ -116,6 +125,7 @@ async def _read_error_payload(response: aiohttp.ClientResponse): if 400 <= r.status <= 499: message, data = await _read_error_payload(r) + logger.error("Client error (%d): %s", r.status, message) raise MemoriApiClientError( status_code=r.status, message=message or _default_client_error_message(r.status), @@ -123,30 +133,37 @@ async def _read_error_payload(response: aiohttp.ClientResponse): ) r.raise_for_status() + logger.debug("Augmentation request successful") return await r.json() except aiohttp.ClientResponseError: raise except (ssl.SSLError, aiohttp.ClientSSLError) as e: + logger.error("SSL/TLS error during augmentation request: %s", e) raise MemoriApiError( "Memori API request failed due to an SSL/TLS certificate error. " "This is often caused by corporate proxies/SSL inspection. " "Try updating your CA certificates and try again." ) from e except (aiohttp.ClientError, asyncio.TimeoutError) as e: + logger.error("Network/timeout error during augmentation request: %s", e) raise MemoriApiError( "Memori API request failed (network/timeout). " "Check your connection and try again." ) from e def delete(self, route): + logger.debug("DELETE request to %s", route) r = self.__session().delete(self.url(route), headers=self.headers()) + logger.debug("DELETE response - status: %d", r.status_code) r.raise_for_status() return r.json() def get(self, route): + logger.debug("GET request to %s", route) r = self.__session().get(self.url(route), headers=self.headers()) + logger.debug("GET response - status: %d", r.status_code) r.raise_for_status() @@ -156,7 +173,9 @@ async def get_async(self, route): return await self.__request_async("GET", route) def patch(self, route, json=None): + logger.debug("PATCH request to %s", route) r = self.__session().patch(self.url(route), headers=self.headers(), json=json) + logger.debug("PATCH response - status: %d", r.status_code) r.raise_for_status() @@ -166,7 +185,9 @@ async def patch_async(self, route, json=None): return await self.__request_async("PATCH", route, json=json) def post(self, route, json=None): + logger.debug("POST request to %s", route) r = self.__session().post(self.url(route), headers=self.headers(), json=json) + logger.debug("POST response - status: %d", r.status_code) r.raise_for_status() @@ -205,23 +226,66 @@ async def __request_async(self, method: str, route: str, json=None): json=json, timeout=aiohttp.ClientTimeout(total=30), ) as r: + logger.debug( + "Async %s response - status: %d, attempt: %d", + method.upper(), + r.status, + attempts + 1, + ) r.raise_for_status() return await r.json() except aiohttp.ClientResponseError as e: if e.status < 500 or e.status > 599: + logger.error( + "Non-retryable error %d for %s %s", + e.status, + method.upper(), + url, + ) raise if attempts >= max_retries: + logger.error( + "Max retries (%d) exceeded for %s %s", + max_retries, + method.upper(), + url, + ) raise sleep = backoff_factor * (2**attempts) + logger.debug( + "Retrying %s %s in %.1fs (attempt %d/%d) after status %d", + method.upper(), + url, + sleep, + attempts + 2, + max_retries, + e.status, + ) await asyncio.sleep(sleep) attempts += 1 - except Exception: + except Exception as e: if attempts >= max_retries: + logger.error( + "Max retries (%d) exceeded for %s %s: %s", + max_retries, + method.upper(), + url, + e, + ) raise sleep = backoff_factor * (2**attempts) + logger.debug( + "Retrying %s %s in %.1fs (attempt %d/%d) after error: %s", + method.upper(), + url, + sleep, + attempts + 2, + max_retries, + e, + ) await asyncio.sleep(sleep) attempts += 1 diff --git a/memori/_search.py b/memori/_search.py index de8fb690..a268ba28 100644 --- a/memori/_search.py +++ b/memori/_search.py @@ -9,11 +9,14 @@ """ import json +import logging from typing import Any import faiss import numpy as np +logger = logging.getLogger(__name__) + def parse_embedding(raw) -> np.ndarray: """Parse embedding from database format to numpy array. @@ -52,6 +55,7 @@ def find_similar_embeddings( List of (id, similarity_score) tuples, sorted by similarity desc """ if not embeddings: + logger.debug("find_similar_embeddings called with empty embeddings") return [] query_dim = len(query_embedding) @@ -72,8 +76,10 @@ def find_similar_embeddings( continue if not embeddings_list: + logger.debug("No valid embeddings after parsing") return [] + logger.debug("Building FAISS index with %d embeddings", len(embeddings_list)) try: embeddings_array = np.stack(embeddings_list, axis=0) except ValueError: @@ -83,6 +89,11 @@ def find_similar_embeddings( query_array = np.asarray([query_embedding], dtype=np.float32) if embeddings_array.shape[1] != query_array.shape[1]: + logger.debug( + "Embedding dimension mismatch: db=%d, query=%d", + embeddings_array.shape[1], + query_array.shape[1], + ) return [] faiss.normalize_L2(query_array) @@ -98,6 +109,14 @@ def find_similar_embeddings( if embedding_idx >= 0 and embedding_idx < len(id_list): results.append((id_list[embedding_idx], float(similarities[0][result_idx]))) + if results: + scores = [round(score, 3) for _, score in results] + logger.debug( + "FAISS similarity search complete - top %d matches: %s", + len(results), + scores, + ) + return results @@ -120,20 +139,29 @@ def search_entity_facts( Returns: List of dicts with keys: id, content, similarity """ + logger.debug( + "Executing memori_entity_fact query - entity_id: %s, embeddings_limit: %s", + entity_id, + embeddings_limit, + ) results = entity_fact_driver.get_embeddings(entity_id, embeddings_limit) if not results: + logger.debug("No embeddings found in database for entity_id: %s", entity_id) return [] + logger.debug("Retrieved %d embeddings from database", len(results)) embeddings = [(row["id"], row["content_embedding"]) for row in results] similar = find_similar_embeddings(embeddings, query_embedding, limit) if not similar: + logger.debug("No similar embeddings found") return [] top_ids = [fact_id for fact_id, _ in similar] similarities_map = dict(similar) + logger.debug("Fetching content for %d fact IDs", len(top_ids)) content_results = entity_fact_driver.get_facts_by_ids(top_ids) content_map = {row["id"]: row["content"] for row in content_results} @@ -148,4 +176,7 @@ def search_entity_facts( } ) + logger.debug( + "Returning %d facts with similarity scores", len(facts_with_similarity) + ) return facts_with_similarity diff --git a/memori/llm/_base.py b/memori/llm/_base.py index 8f229843..7732e185 100644 --- a/memori/llm/_base.py +++ b/memori/llm/_base.py @@ -11,11 +11,13 @@ import asyncio import copy import json +import logging from typing import TYPE_CHECKING from google.protobuf import json_format from memori._config import Config +from memori._logging import truncate from memori._utils import merge_chunk if TYPE_CHECKING: @@ -33,6 +35,8 @@ provider_is_langchain, ) +logger = logging.getLogger(__name__) + class BaseClient: def __init__(self, config: Config): @@ -419,11 +423,14 @@ def inject_recalled_facts(self, kwargs: dict) -> dict: if not user_query: return kwargs + logger.debug("User query: %s", truncate(user_query)) + from memori.memory.recall import Recall facts = Recall(self.config).search_facts(user_query, entity_id=entity_id) if not facts: + logger.debug("No facts found to inject into prompt") return kwargs relevant_facts = [ @@ -433,8 +440,13 @@ def inject_recalled_facts(self, kwargs: dict) -> dict: ] if not relevant_facts: + logger.debug( + "No facts above relevance threshold (%.2f)", + self.config.recall_relevance_threshold, + ) return kwargs + logger.debug("Injecting %d recalled facts into prompt", len(relevant_facts)) fact_lines = [f"- {fact['content']}" for fact in relevant_facts] recall_context = ( "\n\n\n" @@ -480,6 +492,7 @@ def inject_conversation_messages(self, kwargs: dict) -> dict: return kwargs self._injected_message_count = len(messages) + logger.debug("Injecting %d conversation messages from history", len(messages)) if ( llm_is_openai(self.config.framework.provider, self.config.llm.provider) @@ -657,6 +670,9 @@ def handle_post_response(self, kwargs, start_time, raw_response): else: content = "" + if content: + logger.debug("Response content: %s", truncate(str(content))) + messages_for_aug.append( { "role": "assistant", @@ -679,6 +695,7 @@ def handle_post_response(self, kwargs, start_time, raw_response): conversation_messages=messages_for_aug, system_prompt=system_prompt, ) + logger.debug("Kicking off AA - enqueueing augmentation") self.config.augmentation.enqueue(augmentation_input) diff --git a/memori/llm/_embeddings.py b/memori/llm/_embeddings.py index f0082e3c..7d3c34f1 100644 --- a/memori/llm/_embeddings.py +++ b/memori/llm/_embeddings.py @@ -9,6 +9,7 @@ """ import asyncio +import logging import os import struct from collections.abc import Iterable @@ -18,6 +19,8 @@ from sentence_transformers import SentenceTransformer +logger = logging.getLogger(__name__) + _MODEL_CACHE: dict[str, SentenceTransformer] = {} @@ -65,16 +68,29 @@ def embed_texts( ) -> list[list[float]]: inputs = _prepare_text_inputs(texts) if not inputs: + logger.debug("embed_texts called with empty input") return [] + logger.debug( + "Generating embedding using model: %s for %d text(s)", model, len(inputs) + ) + try: encoder = _get_model(model) except (OSError, RuntimeError, ValueError): + logger.debug("Failed to load model %s, returning zero embeddings", model) return _zero_vectors(len(inputs), fallback_dimension) try: embeddings = encoder.encode(inputs, convert_to_numpy=True) - return embeddings.tolist() + result = embeddings.tolist() + if result: + logger.debug( + "Embedding generated - dimension: %d, count: %d", + len(result[0]), + len(result), + ) + return result except ValueError as e: # Some models can raise "all input arrays must have the same shape" when # encoding batches. Retry one-by-one to avoid internal stacking. @@ -91,12 +107,24 @@ def embed_texts( if len(dim_set) != 1: raise ValueError("all input arrays must have the same shape") from e + if vectors: + logger.debug( + "Embedding generated (one-by-one) - dimension: %d, count: %d", + len(vectors[0]), + len(vectors), + ) return vectors except Exception: dim = _embedding_dimension(encoder, default=fallback_dimension) + logger.debug( + "Embedding encode failed, returning zero embeddings of dim %d", dim + ) return _zero_vectors(len(inputs), dim) except RuntimeError: dim = _embedding_dimension(encoder, default=fallback_dimension) + logger.debug( + "Embedding encode failed, returning zero embeddings of dim %d", dim + ) return _zero_vectors(len(inputs), dim) diff --git a/memori/llm/_invoke.py b/memori/llm/_invoke.py index ce8f304a..489f11c6 100644 --- a/memori/llm/_invoke.py +++ b/memori/llm/_invoke.py @@ -9,12 +9,14 @@ """ import inspect +import logging import time from collections.abc import AsyncIterator, Iterator from botocore.eventstream import EventStream from grpc.experimental.aio import UnaryStreamCall +from memori._logging import truncate from memori._utils import merge_chunk from memori.llm._base import BaseInvoke from memori.llm._iterable import Iterable as MemoriIterable @@ -23,6 +25,8 @@ from memori.llm._streaming import StreamingBody as MemoriStreamingBody from memori.llm._utils import client_is_bedrock +logger = logging.getLogger(__name__) + class Invoke(BaseInvoke): def invoke(self, **kwargs): @@ -32,6 +36,11 @@ def invoke(self, **kwargs): self.inject_recalled_facts(self.configure_for_streaming_usage(kwargs)) ) + logger.debug( + "Sending request to LLM - provider: %s, model: %s", + self.config.llm.provider, + truncate(str(kwargs.get("model", "unknown")), 100), + ) raw_response = self._method(**kwargs) if isinstance(raw_response, Iterator) or inspect.isgenerator(raw_response): @@ -70,6 +79,11 @@ async def invoke(self, **kwargs): self.inject_recalled_facts(self.configure_for_streaming_usage(kwargs)) ) + logger.debug( + "Sending async request to LLM - provider: %s, model: %s", + self.config.llm.provider, + truncate(str(kwargs.get("model", "unknown")), 100), + ) raw_response = await self._method(**kwargs) self.handle_post_response(kwargs, start, raw_response) return raw_response diff --git a/memori/memory/_manager.py b/memori/memory/_manager.py index 81b7a5bf..7a2dd99b 100644 --- a/memori/memory/_manager.py +++ b/memori/memory/_manager.py @@ -8,17 +8,21 @@ memorilabs.ai """ +import logging import warnings from memori._config import Config from memori.memory._writer import Writer +logger = logging.getLogger(__name__) + class Manager: def __init__(self, config: Config): self.config = config def execute(self, payload): + logger.debug("Memory manager execution started") if self.config.enterprise is True: warnings.warn( "Memori Enterprise is not available yet.", @@ -30,5 +34,6 @@ def execute(self, payload): # Collector(self.config).fire_and_forget(payload) Writer(self.config).execute(payload) + logger.debug("Memory manager execution completed") return self diff --git a/memori/memory/_writer.py b/memori/memory/_writer.py index efeb0612..eb84bf14 100644 --- a/memori/memory/_writer.py +++ b/memori/memory/_writer.py @@ -9,6 +9,7 @@ """ import json +import logging import time from sqlalchemy.exc import OperationalError @@ -16,6 +17,8 @@ from memori._config import Config from memori.llm._registry import Registry as LlmRegistry +logger = logging.getLogger(__name__) + MAX_RETRIES = 3 RETRY_BACKOFF_BASE = 0.1 @@ -26,14 +29,19 @@ def __init__(self, config: Config): def execute(self, payload: dict, max_retries: int = MAX_RETRIES) -> "Writer": if self.config.storage is None or self.config.storage.driver is None: + logger.debug("Writer.execute skipped - storage not configured") return self + logger.debug("Writing response to memori DB") for attempt in range(max_retries): try: self._execute_transaction(payload) return self except OperationalError as e: if "restart transaction" in str(e) and attempt < max_retries - 1: + logger.debug( + "Writer retry attempt %d due to OperationalError", attempt + 1 + ) if self.config.storage.adapter: self.config.storage.adapter.rollback() time.sleep(RETRY_BACKOFF_BASE * (2**attempt)) @@ -113,3 +121,7 @@ def _execute_transaction(self, payload: dict) -> None: if self.config.storage is not None and self.config.storage.adapter is not None: self.config.storage.adapter.flush() self.config.storage.adapter.commit() + logger.debug( + "Transaction committed - conversation_id: %s", + self.config.cache.conversation_id, + ) diff --git a/memori/memory/augmentation/_db_writer.py b/memori/memory/augmentation/_db_writer.py index 8a5b6cc3..4d2c12ce 100644 --- a/memori/memory/augmentation/_db_writer.py +++ b/memori/memory/augmentation/_db_writer.py @@ -8,6 +8,7 @@ memorilabs.ai """ +import logging import queue as queue_module import threading import time @@ -15,6 +16,8 @@ from memori.storage._connection import connection_context +logger = logging.getLogger(__name__) + class WriteTask: def __init__( @@ -85,6 +88,7 @@ def _run_loop(self) -> None: if self.conn_factory is None: return + logger.debug("AA DB writer thread started") while True: try: with connection_context(self.conn_factory) as (conn, adapter, driver): @@ -95,6 +99,9 @@ def _run_loop(self) -> None: time.sleep(self.batch_timeout) continue + logger.debug( + "AA DB writer batch started - %d writes", len(batch) + ) try: for task in batch: task.execute(driver) @@ -102,9 +109,11 @@ def _run_loop(self) -> None: if adapter: adapter.flush() adapter.commit() + logger.debug("AA DB writer completing - batch committed") except Exception: import traceback + logger.debug("AA DB writer batch failed - rolling back") traceback.print_exc() if adapter: try: diff --git a/memori/memory/augmentation/_manager.py b/memori/memory/augmentation/_manager.py index 4a3e56fc..f126619f 100644 --- a/memori/memory/augmentation/_manager.py +++ b/memori/memory/augmentation/_manager.py @@ -75,6 +75,7 @@ def enqueue(self, input_data: AugmentationInput) -> "Manager": raise self._quota_error if not self._active or not self.conn_factory: + logger.debug("Augmentation enqueue skipped - not active or no connection") return self runtime = get_runtime() @@ -85,6 +86,7 @@ def enqueue(self, input_data: AugmentationInput) -> "Manager": if runtime.loop is None: raise RuntimeError("Event loop is not available") + logger.debug("AA enqueued - scheduling augmentation processing") future = asyncio.run_coroutine_threadsafe( self._process_augmentations(input_data), runtime.loop ) @@ -109,12 +111,14 @@ def _handle_augmentation_result(self, future: Future[Any]) -> None: async def _process_augmentations(self, input_data: AugmentationInput) -> None: if not self.augmentations: + logger.debug("No augmentations configured") return runtime = get_runtime() if runtime.semaphore is None: return + logger.debug("AA processing started") async with runtime.semaphore: ctx = AugmentationContext(payload=input_data) @@ -123,6 +127,9 @@ async def _process_augmentations(self, input_data: AugmentationInput) -> None: for aug in self.augmentations: if aug.enabled: try: + logger.debug( + "Running augmentation: %s", aug.__class__.__name__ + ) ctx = await aug.process(ctx, driver) except Exception as e: from memori._exceptions import QuotaExceededError @@ -135,6 +142,7 @@ async def _process_augmentations(self, input_data: AugmentationInput) -> None: ) if ctx.writes: + logger.debug("AA scheduling %d DB writes", len(ctx.writes)) self._enqueue_writes(ctx.writes) except Exception as e: from memori._exceptions import QuotaExceededError diff --git a/memori/memory/augmentation/augmentations/memori/_augmentation.py b/memori/memory/augmentation/augmentations/memori/_augmentation.py index 680793c6..6025c2bd 100644 --- a/memori/memory/augmentation/augmentations/memori/_augmentation.py +++ b/memori/memory/augmentation/augmentations/memori/_augmentation.py @@ -8,6 +8,8 @@ memorilabs.ai """ +import logging + from memori._network import Api from memori.llm._embeddings import embed_texts_async from memori.memory._struct import Memories @@ -30,6 +32,8 @@ ) from memori.memory.augmentation._registry import Registry +logger = logging.getLogger(__name__) + @Registry.register("advanced_augmentation") class AdvancedAugmentation(BaseAugmentation): @@ -105,6 +109,7 @@ async def process(self, ctx: AugmentationContext, driver) -> AugmentationContext ctx.payload.process_id, ) + logger.debug("AA submitting payload to API") try: api_response = await api.augmentation_async(payload) except Exception as e: @@ -112,9 +117,11 @@ async def process(self, ctx: AugmentationContext, driver) -> AugmentationContext if isinstance(e, QuotaExceededError): raise + logger.debug("AA API call failed: %s", type(e).__name__) return ctx if not api_response: + logger.debug("AA API returned empty response") return ctx memories = await self._process_api_response(api_response) diff --git a/memori/memory/recall.py b/memori/memory/recall.py index 2da68a1b..1bcbd4c3 100644 --- a/memori/memory/recall.py +++ b/memori/memory/recall.py @@ -8,14 +8,18 @@ memorilabs.ai """ +import logging import time from sqlalchemy.exc import OperationalError from memori._config import Config +from memori._logging import truncate from memori._search import search_entity_facts from memori.llm._embeddings import embed_texts +logger = logging.getLogger(__name__) + MAX_RETRIES = 3 RETRY_BACKOFF_BASE = 0.05 @@ -27,20 +31,32 @@ def __init__(self, config: Config) -> None: def search_facts( self, query: str, limit: int | None = None, entity_id: int | None = None ) -> list[dict]: + logger.debug( + "Recall started - query: %s (%d chars), limit: %s", + truncate(query, 50), + len(query), + limit, + ) + if self.config.storage is None or self.config.storage.driver is None: + logger.debug("Recall aborted - storage not configured") return [] if entity_id is None: if self.config.entity_id is None: + logger.debug("Recall aborted - no entity_id configured") return [] entity_id = self.config.storage.driver.entity.create(self.config.entity_id) + logger.debug("Entity ID resolved: %s", entity_id) if entity_id is None: + logger.debug("Recall aborted - entity_id is None after resolution") return [] if limit is None: limit = self.config.recall_facts_limit + logger.debug("Generating query embedding") embeddings_config = self.config.embeddings query_embedding = embed_texts( query, @@ -51,6 +67,12 @@ def search_facts( facts = [] for attempt in range(MAX_RETRIES): try: + logger.debug( + "Executing search_entity_facts - entity_id: %s, limit: %s, embeddings_limit: %s", + entity_id, + limit, + self.config.recall_embeddings_limit, + ) facts = search_entity_facts( self.config.storage.driver.entity_fact, entity_id, @@ -58,9 +80,13 @@ def search_facts( limit, self.config.recall_embeddings_limit, ) + logger.debug("Recall complete - found %d facts", len(facts)) break except OperationalError as e: if "restart transaction" in str(e) and attempt < MAX_RETRIES - 1: + logger.debug( + "Retry attempt %d due to OperationalError", attempt + 1 + ) time.sleep(RETRY_BACKOFF_BASE * (2**attempt)) continue raise