chore(cli): add loggers. (#81)

* chore(cli): add logger for `main.py`.

* configure the logging module.

* logging for lsp

* do not log to stdio for daemon processes.

* fix broken test

* logger for mcp server.

* coverage for lsp

* logger for chunkers.

* documentation about logging.

* logging for `common.py`

* loggers for clean, drop, init and ls

* logger for `query`

* logger for reranker.

* logger for `vectorise`.

* logger for `update`

* logger for cli_utils

* coverage for `vectorise`

* coverage for `query`

* replace `print` with logger.

* convert log levels to upper case

Author: Davidyz

docs/cli.md

@@ -21,6 +21,7 @@
   * [Removing a Collection](#removing-a-collection)
   * [Checking Project Setup](#checking-project-setup)
   * [Cleaning up](#cleaning-up)
+  * [Debugging and Diagnosing](#debugging-and-diagnosing)
 * [Shell Completion](#shell-completion)
 * [Hardware Acceleration](#hardware-acceleration)
 * [For Developers](#for-developers)
@@ -417,6 +418,20 @@ some_message` and then getting an empty results.
 For empty collections and collections for removed projects, you can use the
 `vectorcode clean` command to remove them at once.
 
+### Debugging and Diagnosing
+
+When something doesn't work as expected, you can enable logging by setting the
+`VECTORCODE_LOG_LEVEL` variable to one of `ERROR`, `WARN` (`WARNING`), `INFO` or
+`DEBUG`. For the CLI that you interact with in your shell, this will output logs
+to `STDERR` and write a log file to `~/.local/share/vectorcode/logs/`. For LSP
+and MCP servers, because `STDIO` is used for the RPC, only the log file will be
+written.
+
+For example:
+```bash
+VECTORCODE_LOG_LEVEL=INFO vectorcode vectorise file1.py file2.lua
+```
+
 ## Shell Completion
 
 VectorCode supports shell completion for bash/zsh/tcsh. You can use `vectorcode -s {bash,zsh,tcsh}`

pyproject.toml

@@ -17,6 +17,7 @@ dependencies = [
     "pygments",
     "transformers>=4.36.0,!=4.51.0,!=4.51.1,!=4.51.2",
     "wheel<0.46.0",
+    "colorlog",
 ]
 requires-python = ">=3.11,<3.14"
 readme = "README.md"

src/vectorcode/chunking.py

@@ -1,3 +1,4 @@
+import logging
 import os
 import re
 from abc import abstractmethod
@@ -14,6 +15,8 @@
 
 from vectorcode.cli_utils import Config
 
+logger = logging.getLogger(name=__name__)
+
 
 @dataclass
 class Chunk:
@@ -50,6 +53,8 @@ def __init__(self, config: Optional[Config] = None) -> None:
         super().__init__(config)
 
     def chunk(self, data: str):
+        logger.info("Started chunking with StringChunker.")
+        logger.debug(f"{data=}")
         if self.config.chunk_size < 0:
             yield Chunk(
                 text=data,
@@ -80,6 +85,7 @@ def __init__(self, config: Optional[Config] = None) -> None:
         super().__init__(config)
 
     def chunk(self, data: TextIOWrapper) -> Generator[Chunk, None, None]:
+        logger.info("Started chunking using FileChunker.", data.name)
         lines = data.readlines()
         if len(lines) == 0:
             return
@@ -137,6 +143,10 @@ def __init__(self, config: Optional[Config] = None):
         super().__init__(config)
 
     def __chunk_node(self, node: Node, text: str) -> Generator[Chunk, None, None]:
+        if node.text is not None:
+            logger.debug(
+                f"Traversing at node {node.text.decode()} at position {node.byte_range}"
+            )
         current_chunk = ""
 
         current_start = None
@@ -225,6 +235,9 @@ def __build_pattern(self, language: str):
         else:
             patterns.extend(self.config.chunk_filters.get("*", []))
         if len(patterns):
+            logger.debug(
+                f"Merging {len(patterns)} filter patterns for excluding chunks."
+            )
             patterns = [f"(?:{i})" for i in patterns]
             return f"(?:{'|'.join(patterns)})"
         return ""
@@ -234,10 +247,15 @@ def chunk(self, data: str) -> Generator[Chunk, None, None]:
         data: path to the file
         """
         assert os.path.isfile(data)
+        logger.info(f"Started chunking {data} with TreeSitterChunker.")
         with open(data) as fin:
             lines = fin.readlines()
             content = "".join(lines)
             if self.config.chunk_size < 0 and content:
+                logger.info(
+                    "Skipping chunking %s because document is smaller than chunk_size.",
+                    data,
+                )
                 yield Chunk(content, Point(1, 0), Point(len(lines), len(lines[-1]) - 1))
                 return
         parser = None
@@ -251,12 +269,17 @@ def chunk(self, data: str) -> Generator[Chunk, None, None]:
                     parser = get_parser(name.lower())
                     if parser is not None:
                         language = name.lower()
+                        logger.debug(
+                            "Detected %s filetype for treesitter chunking.", language
+                        )
                         break
                 except LookupError:  # pragma: nocover
                     pass
 
         if parser is None:
-            # fall back to naive chunking
+            logger.debug(
+                "Unable to pick a suitable parser. Fall back to naive chunking"
+            )
             yield from StringChunker(self.config).chunk(content)
         else:
             pattern_str = self.__build_pattern(language=language)

src/vectorcode/cli_utils.py

@@ -1,8 +1,11 @@
 import argparse
 import glob
 import json
+import logging
 import os
+import sys
 from dataclasses import dataclass, field, fields
+from datetime import datetime
 from enum import Enum, StrEnum
 from pathlib import Path
 from typing import Any, Optional, Sequence, Union
@@ -11,6 +14,9 @@
 
 from vectorcode import __version__
 
+logger = logging.getLogger(name=__name__)
+
+
 PathLike = Union[str, Path]
 
 GLOBAL_CONFIG_PATH = os.path.join(
@@ -395,10 +401,13 @@ async def load_config_file(path: Optional[PathLike] = None):
     if path is None:
         path = GLOBAL_CONFIG_PATH
     if os.path.isfile(path):
+        logger.debug(f"Loading config from {path}")
         with open(path) as fin:
             config = json.load(fin)
         expand_envs_in_dict(config)
         return await Config.import_from(config)
+    else:
+        logger.warning("Loading default config.")
     return Config()
 
 
@@ -410,9 +419,13 @@ async def find_project_config_dir(start_from: PathLike = "."):
         for anchor in project_root_anchors:
             to_be_checked = os.path.join(current_dir, anchor)
             if os.path.isdir(to_be_checked):
+                logger.debug(f"Found root anchor at {str(to_be_checked)}")
                 return to_be_checked
         parent = current_dir.parent
         if parent.resolve() == current_dir:
+            logger.debug(
+                f"Couldn't find project root after reaching {str(current_dir)}"
+            )
             return
         current_dir = parent.resolve()
 
@@ -481,3 +494,58 @@ async def expand_globs(
                 )
             )
     return list(result)
+
+
+def config_logging(
+    name: str = "vectorcode", stdio: bool = True, log_file: bool = False
+):  # pragma: nocover
+    """Configure the logging module. This should be called before a `main` function (CLI, LSP or MCP)."""
+
+    logging.root.handlers = []
+
+    level_from_env = os.environ.get("VECTORCODE_LOG_LEVEL")
+    level = None
+    if level_from_env:
+        level = logging._nameToLevel.get(level_from_env.upper())
+        if level is None:
+            logging.warning(
+                "Invalid log level: %s. Falling back to default levels.", level_from_env
+            )
+
+    handlers = []
+    if level is not None or log_file:
+        log_dir = os.path.expanduser("~/.local/share/vectorcode/logs/")
+        os.makedirs(log_dir, exist_ok=True)
+        # File handler
+        log_file_path = os.path.join(
+            log_dir, f"{name}-{datetime.now().strftime('%Y-%m-%d_%H-%M-%S')}.log"
+        )
+        file_handler = logging.FileHandler(log_file_path)
+        file_handler.setLevel(level or logging.WARN)
+        handlers.append(file_handler)
+
+    if stdio:
+        import colorlog
+
+        # Console handler
+        console_handler = colorlog.StreamHandler(sys.stderr)
+        console_handler.setFormatter(
+            colorlog.ColoredFormatter(
+                fmt="%(log_color)s%(levelname)s%(reset)s: %(name)s : %(message)s",
+                log_colors={
+                    "DEBUG": "cyan",
+                    "INFO": "green",
+                    "WARNING": "yellow",
+                    "ERROR": "red",
+                    "CRITICAL": "bold_red",
+                },
+                reset=True,
+            )
+        )
+        console_handler.setLevel(level or logging.WARN)
+        handlers.append(console_handler)
+
+    logging.basicConfig(
+        handlers=handlers,
+        level=level,
+    )

src/vectorcode/common.py

@@ -1,9 +1,11 @@
 import asyncio
 import hashlib
+import logging
 import os
 import socket
 import subprocess
 import sys
+import traceback
 from typing import AsyncGenerator
 
 import chromadb
@@ -15,6 +17,8 @@
 
 from vectorcode.cli_utils import Config, expand_path
 
+logger = logging.getLogger(name=__name__)
+
 
 async def get_collections(
     client: AsyncClientAPI,
@@ -42,6 +46,7 @@ async def try_server(host: str, port: int):
     try:
         async with httpx.AsyncClient() as client:
             response = await client.get(url=url)
+            logger.debug(f"Chromadb server at {host}:{port} returned {response=}")
             return response.status_code == 200
     except (httpx.ConnectError, httpx.ConnectTimeout):
         return False
@@ -73,15 +78,17 @@ async def start_server(configs: Config):
     if not os.path.isdir(configs.db_log_path):
         os.makedirs(configs.db_log_path)
     if not os.path.isdir(db_path):
-        print(
+        logger.warning(
             f"Using local database at {os.path.expanduser('~/.local/share/vectorcode/chromadb/')}.",
-            file=sys.stderr,
         )
         db_path = os.path.expanduser("~/.local/share/vectorcode/chromadb/")
     env = os.environ.copy()
     with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as s:
         s.bind(("", 0))  # OS selects a free ephemeral port
         configs.port = int(s.getsockname()[1])
+    logger.warning(
+        f"Starting bundled ChromaDB server at {configs.host}:{configs.port}."
+    )
     env.update({"ANONYMIZED_TELEMETRY": "False"})
     process = await asyncio.create_subprocess_exec(
         sys.executable,
@@ -130,10 +137,12 @@ async def get_client(configs: Config) -> AsyncClientAPI:
 def get_collection_name(full_path: str) -> str:
     full_path = str(expand_path(full_path, absolute=True))
     hasher = hashlib.sha256()
-    hasher.update(
-        f"{os.environ.get('USER', os.environ.get('USERNAME', 'DEFAULT_USER'))}@{socket.gethostname()}:{full_path}".encode()
-    )
+    plain_collection_name = f"{os.environ.get('USER', os.environ.get('USERNAME', 'DEFAULT_USER'))}@{socket.gethostname()}:{full_path}"
+    hasher.update(plain_collection_name.encode())
     collection_id = hasher.hexdigest()[:63]
+    logger.debug(
+        f"Hashing {plain_collection_name} as the collection name for {full_path}."
+    )
     return collection_id
 
 
@@ -143,20 +152,18 @@ def get_embedding_function(configs: Config) -> chromadb.EmbeddingFunction | None
             **configs.embedding_params
         )
     except AttributeError:
-        print(
+        logger.warning(
             f"Failed to use {configs.embedding_function}. Falling back to Sentence Transformer.",
-            file=sys.stderr,
         )
         return embedding_functions.SentenceTransformerEmbeddingFunction()
     except Exception as e:
-        print(
-            f"Failed to use {configs.embedding_function} with the following error:",
-            file=sys.stderr,
-        )
         e.add_note(
             "\nFor errors caused by missing dependency, consult the documentation of pipx (or whatever package manager that you installed VectorCode with) for instructions to inject libraries into the virtual environment."
         )
-
+        logger.error(
+            f"Failed to use {configs.embedding_function} with the following error:",
+        )
+        logger.error(traceback.format_exc())
         raise
 
 
@@ -175,6 +182,7 @@ async def get_collection(
     if __COLLECTION_CACHE.get(full_path) is None:
         collection_name = get_collection_name(full_path)
         embedding_function = get_embedding_function(configs)
+
         collection_meta: dict[str, str | int] = {
             "path": full_path,
             "hostname": socket.gethostname(),
@@ -190,7 +198,9 @@ async def get_collection(
                 if not key.startswith("hnsw:"):
                     target_key = f"hnsw:{key}"
                 collection_meta[target_key] = configs.hnsw[key]
-
+        logger.debug(
+            f"Getting/Creating collection with the following metadata: {collection_meta}"
+        )
         if not make_if_missing:
             __COLLECTION_CACHE[full_path] = await client.get_collection(
                 collection_name, embedding_function
@@ -211,6 +221,9 @@ async def get_collection(
                 )
                 or not collection.metadata.get("created-by") == "VectorCode"
             ):
+                logger.error(
+                    f"Failed to use existing collection due to metadata mismatch: {collection_meta}"
+                )
                 raise IndexError(
                     "Failed to create the collection due to hash collision. Please file a bug report."
                 )
@@ -222,15 +235,13 @@ def verify_ef(collection: AsyncCollection, configs: Config):
     collection_ef = collection.metadata.get("embedding_function")
     collection_ep = collection.metadata.get("embedding_params")
     if collection_ef and collection_ef != configs.embedding_function:
-        print(f"The collection was embedded using {collection_ef}.")
-        print(
+        logger.error(f"The collection was embedded using {collection_ef}.")
+        logger.error(
             "Embeddings and query must use the same embedding function and parameters. Please double-check your config."
         )
         return False
     elif collection_ep and collection_ep != configs.embedding_params:
-        print(
-            f"The collection was embedded with a different set of configurations: {collection_ep}.",
-            file=sys.stderr,
+        logger.warning(
+            f"The collection was embedded with a different set of configurations: {collection_ep}. The result may be inaccurate.",
         )
-        print("The result may be inaccurate.", file=sys.stderr)
     return True