From d26f1f794ea6269d10d81cb26be21c6978c321e0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E4=BD=A0=E7=9A=84GitHub=E7=94=A8=E6=88=B7=E5=90=8D?= <2468667813@qq.com> Date: Fri, 25 Sep 2026 14:31:22 +0800 Subject: [PATCH 1/4] feat: add structured ingest logging --- ragframework/pipeline/rag.py | 42 ++++++++++++++++++++++++++++++++- tests/test_pipeline/test_rag.py | 34 ++++++++++++++++++++++++++ 2 files changed, 75 insertions(+), 1 deletion(-) diff --git a/ragframework/pipeline/rag.py b/ragframework/pipeline/rag.py index 63fb64b..ff8f016 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: diff --git a/tests/test_pipeline/test_rag.py b/tests/test_pipeline/test_rag.py index c78f712..4e2b4f2 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,10 +66,42 @@ 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?") From d22f0ed413b480ad59fe9d8a8f18916e6dad40e5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E4=BD=A0=E7=9A=84GitHub=E7=94=A8=E6=88=B7=E5=90=8D?= <2468667813@qq.com> Date: Fri, 25 Sep 2026 14:49:38 +0800 Subject: [PATCH 2/4] feat: log query stage timings --- ragframework/pipeline/rag.py | 19 +++++++++++++++++++ tests/test_pipeline/test_rag.py | 22 ++++++++++++++++++++++ 2 files changed, 41 insertions(+) diff --git a/ragframework/pipeline/rag.py b/ragframework/pipeline/rag.py index ff8f016..96a0eaf 100644 --- a/ragframework/pipeline/rag.py +++ b/ragframework/pipeline/rag.py @@ -262,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) @@ -275,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/tests/test_pipeline/test_rag.py b/tests/test_pipeline/test_rag.py index 4e2b4f2..36e665c 100644 --- a/tests/test_pipeline/test_rag.py +++ b/tests/test_pipeline/test_rag.py @@ -108,6 +108,28 @@ def test_query_returns_response(self, pipeline, tmp_text_file): 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") From fe7b91cac36f0c38faa23904af769e0c5ad27d2e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E4=BD=A0=E7=9A=84GitHub=E7=94=A8=E6=88=B7=E5=90=8D?= <2468667813@qq.com> Date: Fri, 25 Sep 2026 15:27:53 +0800 Subject: [PATCH 3/4] feat: log retriever additions --- ragframework/retriever/chroma.py | 9 +++++++++ ragframework/retriever/faiss.py | 7 +++++++ ragframework/retriever/in_memory.py | 8 ++++++++ tests/test_retriever/test_chroma.py | 19 +++++++++++++++++++ tests/test_retriever/test_faiss.py | 17 +++++++++++++++++ tests/test_retriever/test_in_memory.py | 14 ++++++++++++++ 6 files changed, 74 insertions(+) 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_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) From 2158c87cbecbc89723cade659ae40aa5a583c7e3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E4=BD=A0=E7=9A=84GitHub=E7=94=A8=E6=88=B7=E5=90=8D?= <2468667813@qq.com> Date: Fri, 25 Sep 2026 15:55:10 +0800 Subject: [PATCH 4/4] feat: configure package logging --- CHANGELOG.md | 1 + docs/getting-started.md | 10 ++++++++++ ragframework/__init__.py | 4 ++++ tests/test_logging.py | 11 +++++++++++ 4 files changed, 26 insertions(+) create mode 100644 tests/test_logging.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 613e6be..59bda5b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,7 @@ 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). - PEP 561 `py.typed` marker in source distributions and wheels so downstream type checkers can use the package's annotations (closes #47). - Add an optional `max_chars` limit to `SentenceChunker`. - `RAGConfig.embed_batch_size` so `RAGPipeline.ingest()` embeds chunks in bounded batches (closes #42) 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 e02be82..f9b3e96 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.2.0" __all__ = [ "__version__", 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)