Rework dspy logger (stanfordnlp#1732)

* Rework dspy logger

* add enable/disable logging support

* file rename

dspy/__init__.py

@@ -5,16 +5,18 @@
 from .primitives import *
 from .retrieve import *
 from .signatures import *
-from .utils.logging import logger, set_log_output
 
 # Functional must be imported after primitives, predict and signatures
 from .functional import *  # isort: skip
 from dspy.evaluate import Evaluate # isort: skip
 from dspy.clients import * # isort: skip
 from dspy.adapters import * # isort: skip
+from dspy.utils.logging_utils import configure_dspy_loggers, disable_logging, enable_logging
 
 settings = dsp.settings
 
+configure_dspy_loggers(__name__)
+
 # LM = dsp.LM
 
 AzureOpenAI = dsp.AzureOpenAI

dspy/clients/anyscale.py

@@ -1,9 +1,10 @@
-from typing import Any, Dict, List, Optional
 import json
-import yaml
 import os
+from typing import Any, Dict, List, Optional
+
+import yaml
+import logging
 
-from dspy.utils.logging import logger
 from dspy.clients.finetune import (
     FinetuneJob,
     TrainingMethod,
@@ -18,6 +19,7 @@
 except ImportError:
     anyscale = None
 
+logger = logging.getLogger(__name__)
 
 # List of training methods supported by AnyScale
 TRAINING_METHODS_ANYSCALE = [

dspy/clients/finetune.py

@@ -1,14 +1,15 @@
+import logging
 import os
 from abc import abstractmethod
 from concurrent.futures import Future
 from enum import Enum
 from pathlib import Path
 from typing import Any, Dict, List, Optional
-from dspy.utils.logging import logger
 
 import ujson
 from datasets.fingerprint import Hasher
 
+logger = logging.getLogger(__name__)
 
 def get_finetune_directory() -> str:
     """Get the directory to save the fine-tuned models."""

dspy/clients/lm.py

@@ -1,4 +1,5 @@
 import functools
+import logging
 import os
 import uuid
 from concurrent.futures import ThreadPoolExecutor
@@ -13,7 +14,6 @@
 from dspy.clients.finetune import FinetuneJob, TrainingMethod
 from dspy.clients.lm_finetune_utils import execute_finetune_job, get_provider_finetune_job_class
 from dspy.utils.callback import BaseCallback, with_callbacks
-from dspy.utils.logging import logger
 
 DISK_CACHE_DIR = os.environ.get("DSPY_CACHEDIR") or os.path.join(Path.home(), ".dspy_cache")
 litellm.cache = Cache(disk_cache_dir=DISK_CACHE_DIR, type="disk")
@@ -24,6 +24,8 @@
 
 GLOBAL_HISTORY = []
 
+logger = logging.getLogger(__name__)
+
 
 class LM:
     """

dspy/clients/lm_finetune_utils.py

@@ -1,9 +1,11 @@
+import logging
 from typing import Any, Dict, List, Optional, Type, Union
 
 from dspy.clients.anyscale import FinetuneJobAnyScale, finetune_anyscale
 from dspy.clients.finetune import FinetuneJob, TrainingMethod
 from dspy.clients.openai import FinetuneJobOpenAI, finetune_openai
-from dspy.utils.logging import logger
+
+logger = logging.getLogger(__name__)
 
 _PROVIDER_ANYSCALE = "anyscale"
 _PROVIDER_OPENAI = "openai"

dspy/clients/openai.py

@@ -1,3 +1,4 @@
+import logging
 import re
 import time
 from collections import defaultdict
@@ -12,11 +13,12 @@
     save_data,
     validate_finetune_data,
 )
-from dspy.utils.logging import logger
 
 # Provider name
 PROVIDER_OPENAI = "openai"
 
+logger = logging.getLogger(__name__)
+
 
 def is_openai_model(model: str) -> bool:
     """Check if the model is an OpenAI model."""

dspy/evaluate/evaluate.py

@@ -1,4 +1,5 @@
 import contextlib
+import logging
 import signal
 import sys
 import threading
@@ -42,6 +43,8 @@ def HTML(x: str) -> str:
 # we print the number of failures, the first N examples that failed, and the first N exceptions raised.
 
 
+logger = logging.getLogger(__name__)
+
 class Evaluate:
     def __init__(
         self,
@@ -102,7 +105,7 @@ def interrupt_handler_manager():
 
             def interrupt_handler(sig, frame):
                 self.cancel_jobs.set()
-                dspy.logger.warning("Received SIGINT. Cancelling evaluation.")
+                logger.warning("Received SIGINT. Cancelling evaluation.")
                 default_handler(sig, frame)
 
             signal.signal(signal.SIGINT, interrupt_handler)
@@ -135,7 +138,7 @@ def cancellable_wrapped_program(idx, arg):
             pbar.close()
 
         if self.cancel_jobs.is_set():
-            dspy.logger.warning("Evaluation was cancelled. The results may be incomplete.")
+            logger.warning("Evaluation was cancelled. The results may be incomplete.")
             raise KeyboardInterrupt
 
         return reordered_devset, ncorrect, ntotal
@@ -193,11 +196,11 @@ def wrapped_program(example_idx, example):
                     raise e
 
                 if self.provide_traceback:
-                    dspy.logger.error(
+                    logger.error(
                         f"Error for example in dev set: \t\t {e}\n\twith inputs:\n\t\t{example.inputs()}\n\nStack trace:\n\t{traceback.format_exc()}"
                     )
                 else:
-                    dspy.logger.error(
+                    logger.error(
                         f"Error for example in dev set: \t\t {e}. Set `provide_traceback=True` to see the stack trace."
                     )
 
@@ -219,7 +222,7 @@ def wrapped_program(example_idx, example):
                 display_progress,
             )
 
-        dspy.logger.info(f"Average Metric: {ncorrect} / {ntotal} ({round(100 * ncorrect / ntotal, 1)}%)")
+        logger.info(f"Average Metric: {ncorrect} / {ntotal} ({round(100 * ncorrect / ntotal, 1)}%)")
 
         predicted_devset = sorted(reordered_devset)
 

dspy/primitives/assertions.py

@@ -1,10 +1,12 @@
 import inspect
+import logging
 import uuid
 from typing import Any
 
 import dsp
 import dspy
 
+logger = logging.getLogger(__name__)
 #################### Assertion Helpers ####################
 
 
@@ -82,10 +84,10 @@ def __call__(self) -> bool:
             if self.result:
                 return True
             elif dspy.settings.bypass_assert:
-                dspy.logger.error(f"AssertionError: {self.msg}")
+                logger.error(f"AssertionError: {self.msg}")
                 return True
             else:
-                dspy.logger.error(f"AssertionError: {self.msg}")
+                logger.error(f"AssertionError: {self.msg}")
                 raise DSPyAssertionError(
                     id=self.id,
                     msg=self.msg,
@@ -105,10 +107,10 @@ def __call__(self) -> Any:
             if self.result:
                 return True
             elif dspy.settings.bypass_suggest:
-                dspy.logger.info(f"SuggestionFailed: {self.msg}")
+                logger.info(f"SuggestionFailed: {self.msg}")
                 return True
             else:
-                dspy.logger.info(f"SuggestionFailed: {self.msg}")
+                logger.info(f"SuggestionFailed: {self.msg}")
                 raise DSPySuggestionError(
                     id=self.id,
                     msg=self.msg,
@@ -248,7 +250,7 @@ def wrapper(*args, **kwargs):
                                 dspy.settings.backtrack_to = dsp.settings.trace[-1][0]
 
                             if dspy.settings.backtrack_to is None:
-                                dspy.logger.error("Module not found in trace. If passing a DSPy Signature, please specify the intended module for the assertion (e.g., use `target_module = self.my_module(my_signature)` instead of `target_module =  my_signature`).")
+                                logger.error("Module not found in trace. If passing a DSPy Signature, please specify the intended module for the assertion (e.g., use `target_module = self.my_module(my_signature)` instead of `target_module =  my_signature`).")
 
                             # save unique feedback message for predictor
                             if error_msg not in dspy.settings.predictor_feedbacks.setdefault(
@@ -277,7 +279,7 @@ def wrapper(*args, **kwargs):
                             error_op.pop("_assert_traces", None)
 
                         else:
-                            dspy.logger.error(
+                            logger.error(
                                 "UNREACHABLE: No trace available, this should not happen. Is this run time?",
                             )
 
@@ -316,7 +318,7 @@ def assert_transform_module(
             "Module must have a forward method to have assertions handled.",
         )
     if getattr(module, "_forward", False):
-        dspy.logger.info(
+        logger.info(
             f"Module {module.__class__.__name__} already has a _forward method. Skipping...",
         )
         pass  # TODO warning: might be overwriting a previous _forward method

dspy/retrieve/faiss_rm.py

@@ -2,6 +2,7 @@
 Author: Jagane Sundar: https://github.com/jagane.
 """
 
+import logging
 from typing import Optional, Union
 
 import numpy as np
@@ -23,6 +24,7 @@
     )
 
 
+logger = logging.getLogger(__name__)
 class FaissRM(dspy.Retrieve):
     """A retrieval module that uses an in-memory Faiss to return the top passages for a given query.
 
@@ -80,7 +82,7 @@ def __init__(self, document_chunks, vectorizer=None, k: int = 3):
         embeddings = self._vectorizer(document_chunks)
         xb = np.array(embeddings)
         d = len(xb[0])
-        dspy.logger.info(f"FaissRM: embedding size={d}")
+        logger.info(f"FaissRM: embedding size={d}")
         if len(xb) < 100:
             self._faiss_index = faiss.IndexFlatL2(d)
             self._faiss_index.add(xb)
@@ -92,7 +94,7 @@ def __init__(self, document_chunks, vectorizer=None, k: int = 3):
             self._faiss_index.train(xb)
             self._faiss_index.add(xb)
 
-        dspy.logger.info(f"{self._faiss_index.ntotal} vectors in faiss index")
+        logger.info(f"{self._faiss_index.ntotal} vectors in faiss index")
         self._document_chunks = document_chunks  # save the input document chunks
 
         super().__init__(k=k)
@@ -101,9 +103,9 @@ def _dump_raw_results(self, queries, index_list, distance_list) -> None:
         for i in range(len(queries)):
             indices = index_list[i]
             distances = distance_list[i]
-            dspy.logger.debug(f"Query: {queries[i]}")
+            logger.debug(f"Query: {queries[i]}")
             for j in range(len(indices)):
-                dspy.logger.debug(f"    Hit {j} = {indices[j]}/{distances[j]}: {self._document_chunks[indices[j]]}")
+                logger.debug(f"    Hit {j} = {indices[j]}/{distances[j]}: {self._document_chunks[indices[j]]}")
         return
 
     def forward(self, query_or_queries: Union[str, list[str]], k: Optional[int] = None, **kwargs) -> dspy.Prediction:

dspy/teleprompt/bootstrap.py

@@ -1,11 +1,14 @@
-import dspy
-import tqdm
+import logging
 import random
 import threading
-
 from typing import Dict, Optional
-from .vanilla import LabeledFewShot
+
+import tqdm
+
+import dspy
+
 from .teleprompt import Teleprompter
+from .vanilla import LabeledFewShot
 
 # TODO: metrics should return an object with __bool__ basically, but fine if they're more complex.
 # They can also be sortable.
@@ -28,6 +31,8 @@
 
 # TODO: Add baselines=[...]
 
+logger = logging.getLogger(__name__)
+
 class BootstrapFewShot(Teleprompter):
     def __init__(
         self,
@@ -207,7 +212,7 @@ def _bootstrap_one_example(self, example, round_idx=0):
                 current_error_count = self.error_count
             if current_error_count >= self.max_errors:
                 raise e
-            dspy.logger.error(f"Failed to run or to evaluate example {example} with {self.metric} due to {e}.")
+            logger.error(f"Failed to run or to evaluate example {example} with {self.metric} due to {e}.")
 
         if success:
             for step in trace: