diff --git a/CHANGELOG.md b/CHANGELOG.md index de016bf..57af8d2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added +- Structured logging for ingest, query, and retriever stages, including timing and empty-ingest warnings (closes #41). +- ## Fixed - `TextFileLoader` and `MarkdownLoader` now convert Unicode decoding and unknown encoding errors to `LoaderError`, with configurable text decoding error handling (closes #24). diff --git a/docs/getting-started.md b/docs/getting-started.md index 40c62d4..0c8b212 100644 --- a/docs/getting-started.md +++ b/docs/getting-started.md @@ -174,7 +174,17 @@ The example demonstrates the complete RAG workflow: 6\. Generate an answer from the retrieved context. +## Logging +RAG Framework uses Python's standard-library logging and is silent by default. +Enable pipeline stage summaries with: + +```python +import logging +logging.basicConfig(level=logging.INFO) +``` + +Use `logging.DEBUG` to include per-batch embedding and retriever indexing details. \## Building a Pipeline diff --git a/ragframework/__init__.py b/ragframework/__init__.py index 7555655..99a4643 100644 --- a/ragframework/__init__.py +++ b/ragframework/__init__.py @@ -1,5 +1,7 @@ """RAG Framework — a modular, extensible Python framework for RAG pipelines.""" +import logging + from ragframework.base import ( Chunk, Document, @@ -14,6 +16,8 @@ from ragframework.config import RAGConfig from ragframework.pipeline.rag import RAGPipeline +logging.getLogger("ragframework").addHandler(logging.NullHandler()) + __version__ = "0.3.0" __all__ = [ "__version__", diff --git a/ragframework/pipeline/rag.py b/ragframework/pipeline/rag.py index 63fb64b..96a0eaf 100644 --- a/ragframework/pipeline/rag.py +++ b/ragframework/pipeline/rag.py @@ -2,6 +2,8 @@ from __future__ import annotations +import logging +import time from collections.abc import Iterable from ragframework.base import ( @@ -18,6 +20,8 @@ from ragframework.document.chunkers import FixedSizeChunker from ragframework.exceptions import PipelineError +logger = logging.getLogger(__name__) + class RAGPipeline: """Orchestrates the full RAG workflow: load → chunk → embed → index → query. @@ -128,6 +132,12 @@ def ingest(self, source: str) -> int: except Exception as exc: raise PipelineError(f"Loading failed for '{source}': {exc}") from exc + logger.info( + "Loaded documents source=%s documents=%d", + source, + len(documents), + ) + all_chunks: list[Chunk] = [] for doc in documents: try: @@ -136,18 +146,42 @@ def ingest(self, source: str) -> int: raise PipelineError(f"Chunking failed for document '{doc.id}': {exc}") from exc all_chunks.extend(chunks) + logger.info( + "Produced chunks source=%s chunks=%d", + source, + len(all_chunks), + ) + if not all_chunks: + logger.warning("Ingest produced no chunks for source %s", source) return 0 batch_size = self.config.embed_batch_size embeddings: list[list[float]] = [] + embedding_start = time.perf_counter() + try: for start in range(0, len(all_chunks), batch_size): batch = all_chunks[start : start + batch_size] - embeddings.extend(self.embedder.embed([c.content for c in batch])) + batch_embeddings = self.embedder.embed([chunk.content for chunk in batch]) + embeddings.extend(batch_embeddings) + logger.debug( + "Embedded batch source=%s batch=%d chunks=%d", + source, + start // batch_size + 1, + len(batch), + ) except Exception as exc: raise PipelineError(f"Embedding failed: {exc}") from exc + embedding_seconds = time.perf_counter() - embedding_start + logger.info( + "Embedded chunks source=%s chunks=%d embedding_seconds=%.6f", + source, + len(all_chunks), + embedding_seconds, + ) + for embedding in embeddings: self._validate_embedding_dimension(embedding) @@ -159,6 +193,12 @@ def ingest(self, source: str) -> int: except Exception as exc: raise PipelineError(f"Indexing failed: {exc}") from exc + logger.info( + "Indexed chunks source=%s indexed=%d", + source, + len(all_chunks), + ) + return len(all_chunks) def ingest_many(self, sources: Iterable[str]) -> int: @@ -222,11 +262,21 @@ def query(self, query: str, *, top_k: int | None = None) -> RAGResponse: if retrieve_k is None: retrieve_k = final_top_k * 4 if self.reranker is not None else final_top_k + retrieval_start = time.perf_counter() + try: chunks = self.retriever.retrieve(query_embedding, top_k=retrieve_k) except Exception as exc: raise PipelineError(f"Retrieval failed: {exc}") from exc + retrieval_seconds = time.perf_counter() - retrieval_start + logger.info( + "Retrieved chunks top_k=%d retrieved=%d retrieval_seconds=%.6f", + final_top_k, + len(chunks), + retrieval_seconds, + ) + if self.reranker is not None: try: chunks = self.reranker.rerank(query, chunks, top_k=final_top_k) @@ -235,9 +285,18 @@ def query(self, query: str, *, top_k: int | None = None) -> RAGResponse: else: chunks = chunks[:final_top_k] + generation_start = time.perf_counter() + try: answer = self.generator.generate(query, chunks) except Exception as exc: raise PipelineError(f"Generation failed: {exc}") from exc + generation_seconds = time.perf_counter() - generation_start + logger.info( + "Generated answer chunks=%d generation_seconds=%.6f", + len(chunks), + generation_seconds, + ) + return RAGResponse(answer=answer, source_chunks=chunks, query=query) diff --git a/ragframework/retriever/chroma.py b/ragframework/retriever/chroma.py index 0323b4d..657eba4 100644 --- a/ragframework/retriever/chroma.py +++ b/ragframework/retriever/chroma.py @@ -3,12 +3,15 @@ from __future__ import annotations import json +import logging from collections.abc import Mapping, Sequence from typing import Any from ragframework.base import Chunk, Retriever from ragframework.exceptions import RetrieverError +logger = logging.getLogger(__name__) + class ChromaRetriever(Retriever): """Retriever backed by ChromaDB. @@ -76,6 +79,12 @@ def add(self, chunks: list[Chunk]) -> None: except Exception as exc: raise RetrieverError(f"Failed to add chunks to ChromaDB: {exc}") from exc + logger.debug( + "Added chunks count=%d dimension=%d", + len(chunks), + len(embeddings[0]), + ) + def retrieve( self, query_embedding: list[float], diff --git a/ragframework/retriever/faiss.py b/ragframework/retriever/faiss.py index 8792ea7..93f7de5 100644 --- a/ragframework/retriever/faiss.py +++ b/ragframework/retriever/faiss.py @@ -2,6 +2,7 @@ from __future__ import annotations +import logging from typing import Any import numpy as np @@ -17,6 +18,7 @@ from ragframework.exceptions import RetrieverError from ragframework.utils.vectors import validate_vector +logger = logging.getLogger(__name__) _INSTALL_HINT = ( "FAISS support requires 'ragframework[faiss]'. Install it with: pip install ragframework[faiss]" ) @@ -99,6 +101,11 @@ def add(self, chunks: list[Chunk]) -> None: self._index = new_index self._dimension = expected_dimension self._chunks.extend(chunks) + logger.debug( + "Added chunks count=%d dimension=%d", + len(chunks), + matrix.shape[1], + ) def retrieve(self, query_embedding: list[float], top_k: int = 5) -> list[Chunk]: """Return up to ``top_k`` chunks ordered by approximate cosine similarity. diff --git a/ragframework/retriever/in_memory.py b/ragframework/retriever/in_memory.py index 6393f5f..104b38e 100644 --- a/ragframework/retriever/in_memory.py +++ b/ragframework/retriever/in_memory.py @@ -2,6 +2,7 @@ from __future__ import annotations +import logging from typing import Any import numpy as np @@ -10,6 +11,8 @@ from ragframework.exceptions import RetrieverError from ragframework.utils.vectors import validate_vector +logger = logging.getLogger(__name__) + class InMemoryRetriever(Retriever): """A simple retriever that stores chunks in RAM and ranks by cosine similarity. @@ -58,6 +61,11 @@ def add(self, chunks: list[Chunk]) -> None: self._matrix = matrix self._dimension = expected_dimension self._chunks.extend(chunks) + logger.debug( + "Added chunks count=%d dimension=%d", + len(chunks), + matrix.shape[1], + ) def retrieve(self, query_embedding: list[float], top_k: int = 5) -> list[Chunk]: """Rank chunks by cosine similarity. diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 0000000..c54bfa6 --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,11 @@ +"""Tests for package logging configuration.""" + +import importlib +import logging + + +def test_package_logger_has_null_handler(): + importlib.import_module("ragframework") + logger = logging.getLogger("ragframework") + + assert any(isinstance(handler, logging.NullHandler) for handler in logger.handlers) diff --git a/tests/test_pipeline/test_rag.py b/tests/test_pipeline/test_rag.py index c78f712..36e665c 100644 --- a/tests/test_pipeline/test_rag.py +++ b/tests/test_pipeline/test_rag.py @@ -2,6 +2,8 @@ from __future__ import annotations +import logging + import pytest from ragframework.base import Chunk, Embedder, Generator, Reranker @@ -64,16 +66,70 @@ def embed(self, texts: list[str]) -> list[list[float]]: class TestRAGPipeline: + def test_ingest_logs_stage_summaries(self, pipeline, tmp_text_file, caplog): + with caplog.at_level(logging.INFO, logger="ragframework.pipeline.rag"): + count = pipeline.ingest(tmp_text_file) + + messages = [ + record.getMessage() + for record in caplog.records + if record.name == "ragframework.pipeline.rag" + ] + + assert count == 1 + assert f"Loaded documents source={tmp_text_file} documents=1" in messages + assert f"Produced chunks source={tmp_text_file} chunks=1" in messages + assert any( + message.startswith( + f"Embedded chunks source={tmp_text_file} " "chunks=1 embedding_seconds=" + ) + for message in messages + ) + assert f"Indexed chunks source={tmp_text_file} indexed=1" in messages + def test_ingest_returns_chunk_count(self, pipeline, tmp_text_file): count = pipeline.ingest(tmp_text_file) assert count > 0 + def test_ingest_warns_when_source_produces_no_chunks(self, pipeline, tmp_path, caplog): + empty_file = tmp_path / "empty.txt" + empty_file.write_text("", encoding="utf-8") + + with caplog.at_level(logging.WARNING, logger="ragframework.pipeline.rag"): + count = pipeline.ingest(str(empty_file)) + + assert count == 0 + assert str(empty_file) in caplog.text + assert "no chunks" in caplog.text.lower() + def test_query_returns_response(self, pipeline, tmp_text_file): pipeline.ingest(tmp_text_file) response = pipeline.query("What is this about?") assert response.answer assert isinstance(response.source_chunks, list) + def test_query_logs_retrieval_and_generation_summaries(self, pipeline, tmp_text_file, caplog): + pipeline.ingest(tmp_text_file) + caplog.clear() + + with caplog.at_level(logging.INFO, logger="ragframework.pipeline.rag"): + pipeline.query("test", top_k=1) + + messages = [ + record.getMessage() + for record in caplog.records + if record.name == "ragframework.pipeline.rag" + ] + + assert any( + message.startswith("Retrieved chunks top_k=1 retrieved=1 retrieval_seconds=") + for message in messages + ) + assert any( + message.startswith("Generated answer chunks=1 generation_seconds=") + for message in messages + ) + def test_query_top_k_respected(self, pipeline, tmp_text_file): pipeline.ingest(tmp_text_file) response = pipeline.query("test") diff --git a/tests/test_retriever/test_chroma.py b/tests/test_retriever/test_chroma.py index 1b00dd2..a46bbca 100644 --- a/tests/test_retriever/test_chroma.py +++ b/tests/test_retriever/test_chroma.py @@ -1,5 +1,6 @@ """Tests for ChromaRetriever.""" +import logging from pathlib import Path import pytest @@ -62,6 +63,24 @@ def test_add_and_retrieve(): assert results[0].metadata["source"] == "test.txt" +def test_add_logs_count_and_dimension(caplog): + retriever = ChromaRetriever( + collection_name="test_add_logging", + ) + chunks = [ + make_chunk("log-1", [1.0, 0.0, 0.0]), + make_chunk("log-2", [0.0, 1.0, 0.0]), + ] + + with caplog.at_level( + logging.DEBUG, + logger="ragframework.retriever.chroma", + ): + retriever.add(chunks) + + assert "Added chunks count=2 dimension=3" in caplog.text + + def test_retrieve_top_k_limited(): retriever = ChromaRetriever( collection_name="test_top_k", diff --git a/tests/test_retriever/test_faiss.py b/tests/test_retriever/test_faiss.py index 5962c8f..c180502 100644 --- a/tests/test_retriever/test_faiss.py +++ b/tests/test_retriever/test_faiss.py @@ -1,5 +1,6 @@ """Tests for the FAISS-backed retriever.""" +import logging import subprocess import sys @@ -51,6 +52,22 @@ def test_batches_append_without_replacing_existing_chunks() -> None: assert retriever.retrieve([0.0, 1.0, 0.0], top_k=2)[0] is second +def test_add_logs_count_and_dimension(caplog) -> None: + retriever = FAISSRetriever() + chunks = [ + make_chunk("first", [1.0, 0.0, 0.0]), + make_chunk("second", [0.0, 1.0, 0.0]), + ] + + with caplog.at_level( + logging.DEBUG, + logger="ragframework.retriever.faiss", + ): + retriever.add(chunks) + + assert "Added chunks count=2 dimension=3" in caplog.text + + def test_hnsw_index_uses_configured_parameters_and_inner_product() -> None: retriever = FAISSRetriever(m=12, ef_construction=48, ef_search=24) retriever.add([make_chunk("one", [1.0, 0.0])]) diff --git a/tests/test_retriever/test_in_memory.py b/tests/test_retriever/test_in_memory.py index 16b558b..88fb664 100644 --- a/tests/test_retriever/test_in_memory.py +++ b/tests/test_retriever/test_in_memory.py @@ -1,5 +1,7 @@ """Tests for InMemoryRetriever.""" +import logging + import pytest from ragframework.base import Chunk @@ -22,6 +24,18 @@ def test_add_and_retrieve(self, embedded_chunks): r.add(embedded_chunks) assert len(r) == len(embedded_chunks) + def test_add_logs_count_and_dimension(self, embedded_chunks, caplog): + retriever = InMemoryRetriever() + chunks = embedded_chunks[:2] + + with caplog.at_level( + logging.DEBUG, + logger="ragframework.retriever.in_memory", + ): + retriever.add(chunks) + + assert "Added chunks count=2 dimension=16" in caplog.text + def test_retrieve_top_k_limited(self, embedded_chunks): r = InMemoryRetriever() r.add(embedded_chunks)