feat: add structured logging across pipeline stages

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).
 

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
 

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__",

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)

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],

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.

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.

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)

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")

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",