From a8492a0053025000abca72ba66a837d8afac96fe Mon Sep 17 00:00:00 2001 From: Chen Qian Date: Fri, 1 Nov 2024 04:00:27 -0700 Subject: [PATCH] Rework dspy logger (#1732) * Rework dspy logger * add enable/disable logging support * file rename --- dspy/__init__.py | 4 +- dspy/clients/anyscale.py | 8 +- dspy/clients/finetune.py | 3 +- dspy/clients/lm.py | 4 +- dspy/clients/lm_finetune_utils.py | 4 +- dspy/clients/openai.py | 4 +- dspy/evaluate/evaluate.py | 13 +-- dspy/primitives/assertions.py | 16 ++-- dspy/retrieve/faiss_rm.py | 10 ++- dspy/teleprompt/bootstrap.py | 15 ++-- dspy/teleprompt/copro_optimizer.py | 29 ++++--- dspy/teleprompt/finetune_teleprompter.py | 4 +- dspy/teleprompt/mipro_optimizer_v2.py | 94 ++++++++++----------- dspy/utils/__init__.py | 2 +- dspy/utils/logging.py | 100 ----------------------- dspy/utils/logging_utils.py | 83 +++++++++++++++++++ 16 files changed, 203 insertions(+), 190 deletions(-) delete mode 100644 dspy/utils/logging.py create mode 100644 dspy/utils/logging_utils.py diff --git a/dspy/__init__.py b/dspy/__init__.py index 9120f5625..84d360065 100644 --- a/dspy/__init__.py +++ b/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 diff --git a/dspy/clients/anyscale.py b/dspy/clients/anyscale.py index 22d87e8ba..d6867fe26 100644 --- a/dspy/clients/anyscale.py +++ b/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 = [ diff --git a/dspy/clients/finetune.py b/dspy/clients/finetune.py index 2920cdac0..54ba7b4ba 100644 --- a/dspy/clients/finetune.py +++ b/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.""" diff --git a/dspy/clients/lm.py b/dspy/clients/lm.py index 02fe17402..5bb12b406 100644 --- a/dspy/clients/lm.py +++ b/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: """ diff --git a/dspy/clients/lm_finetune_utils.py b/dspy/clients/lm_finetune_utils.py index c9b4863d0..23f300aff 100644 --- a/dspy/clients/lm_finetune_utils.py +++ b/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" diff --git a/dspy/clients/openai.py b/dspy/clients/openai.py index ec084fe5f..0522475f8 100644 --- a/dspy/clients/openai.py +++ b/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.""" diff --git a/dspy/evaluate/evaluate.py b/dspy/evaluate/evaluate.py index 4ca43ad39..7a585a54a 100644 --- a/dspy/evaluate/evaluate.py +++ b/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) diff --git a/dspy/primitives/assertions.py b/dspy/primitives/assertions.py index 4ddea6760..d3f3c4cd5 100644 --- a/dspy/primitives/assertions.py +++ b/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 diff --git a/dspy/retrieve/faiss_rm.py b/dspy/retrieve/faiss_rm.py index c551eacde..587b962c0 100755 --- a/dspy/retrieve/faiss_rm.py +++ b/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: diff --git a/dspy/teleprompt/bootstrap.py b/dspy/teleprompt/bootstrap.py index b17244828..3b02b38b4 100644 --- a/dspy/teleprompt/bootstrap.py +++ b/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: diff --git a/dspy/teleprompt/copro_optimizer.py b/dspy/teleprompt/copro_optimizer.py index 49c693eb3..eb012c273 100644 --- a/dspy/teleprompt/copro_optimizer.py +++ b/dspy/teleprompt/copro_optimizer.py @@ -1,3 +1,4 @@ +import logging from collections import defaultdict import dsp @@ -6,6 +7,8 @@ from dspy.signatures import Signature from dspy.teleprompt.teleprompt import Teleprompter +logger = logging.getLogger(__name__) + """ USAGE SUGGESTIONS: @@ -107,8 +110,8 @@ def _drop_duplicates(self, candidates): def _print_signature(self, predictor): signature = self._get_signature(predictor) - dspy.logger.debug(f"i: {signature.instructions}") - dspy.logger.debug(f"p: {list(signature.fields.values())[-1].json_schema_extra['prefix']}") + logger.debug(f"i: {signature.instructions}") + logger.debug(f"p: {list(signature.fields.values())[-1].json_schema_extra['prefix']}") def _get_signature(self, predictor): if hasattr(predictor, "extended_signature"): @@ -177,7 +180,7 @@ def compile(self, student, *, trainset, eval_kwargs): evaluated_candidates[id(predictor)] = {} if self.prompt_model: - dspy.logger.debug(f"{self.prompt_model.inspect_history(n=1)}") + logger.debug(f"{self.prompt_model.inspect_history(n=1)}") latest_candidates = candidates all_candidates = candidates @@ -188,7 +191,7 @@ def compile(self, student, *, trainset, eval_kwargs): for d in range( self.depth, ): # TODO: fix this so that we eval the new batch of predictors with the new best following predictors - dspy.logger.info(f"Iteration Depth: {d+1}/{self.depth}.") + logger.info(f"Iteration Depth: {d+1}/{self.depth}.") latest_scores = [] @@ -221,19 +224,19 @@ def compile(self, student, *, trainset, eval_kwargs): # Score the instruction / prefix for i, predictor in enumerate(module_clone.predictors()): - dspy.logger.debug(f"Predictor {i+1}") + logger.debug(f"Predictor {i+1}") self._print_signature(predictor) - dspy.logger.info( + logger.info( f"At Depth {d+1}/{self.depth}, Evaluating Prompt Candidate #{c_i+1}/{len(candidates_)} for " f"Predictor {p_i+1} of {len(module.predictors())}.", ) score = evaluate(module_clone, devset=trainset, **eval_kwargs) if self.prompt_model: - dspy.logger.debug(f"prompt_model.inspect_history(n=1) {self.prompt_model.inspect_history(n=1)}") + logger.debug(f"prompt_model.inspect_history(n=1) {self.prompt_model.inspect_history(n=1)}") total_calls += 1 replace_entry = True - dspy.logger.debug(f"(instruction, prefix) {(instruction, prefix)}") + logger.debug(f"(instruction, prefix) {(instruction, prefix)}") if (instruction, prefix) in evaluated_candidates[id(p_old)]: if evaluated_candidates[id(p_old)][(instruction, prefix)]["score"] >= score: replace_entry = False @@ -269,13 +272,13 @@ def compile(self, student, *, trainset, eval_kwargs): ) self._set_signature(p_new, updated_signature) - dspy.logger.debug( + logger.debug( f"Updating Predictor {id(p_old)} to:\ni: {best_candidate['instruction']}\n" f"p: {best_candidate['prefix']}", ) - dspy.logger.debug("Full predictor with update: ") + logger.debug("Full predictor with update: ") for i, predictor in enumerate(module_clone.predictors()): - dspy.logger.debug(f"Predictor {i}") + logger.debug(f"Predictor {i}") self._print_signature(predictor) if d == self.depth - 1: @@ -322,7 +325,7 @@ def compile(self, student, *, trainset, eval_kwargs): )(attempted_instructions=attempts) if self.prompt_model: - dspy.logger.debug( + logger.debug( f"(self.prompt_model.inspect_history(n=1)) {self.prompt_model.inspect_history(n=1)}" ) # Get candidates for each predictor @@ -333,7 +336,7 @@ def compile(self, student, *, trainset, eval_kwargs): ) if self.prompt_model: - dspy.logger.debug(f"{self.prompt_model.inspect_history(n=1)}") + logger.debug(f"{self.prompt_model.inspect_history(n=1)}") latest_candidates = new_candidates candidates = [] diff --git a/dspy/teleprompt/finetune_teleprompter.py b/dspy/teleprompt/finetune_teleprompter.py index c519035d0..315434aba 100644 --- a/dspy/teleprompt/finetune_teleprompter.py +++ b/dspy/teleprompt/finetune_teleprompter.py @@ -1,3 +1,4 @@ +import logging from typing import Any, Callable, Dict, List, Optional, Union import dspy @@ -5,7 +6,8 @@ from dspy.primitives.example import Example from dspy.primitives.prediction import Prediction from dspy.primitives.program import Program -from dspy.utils.logging import logger + +logger = logging.getLogger(__name__) # TODO: Shared below are useful functions. Similar procedures are implemented diff --git a/dspy/teleprompt/mipro_optimizer_v2.py b/dspy/teleprompt/mipro_optimizer_v2.py index ef63c6764..6f1ffb762 100644 --- a/dspy/teleprompt/mipro_optimizer_v2.py +++ b/dspy/teleprompt/mipro_optimizer_v2.py @@ -1,17 +1,18 @@ +import logging import random -import sys import textwrap from collections import defaultdict from typing import Any, Callable, Dict, List, Optional, Tuple import numpy as np import optuna -import dspy +import dspy from dspy.evaluate.evaluate import Evaluate from dspy.propose import GroundedProposer from dspy.teleprompt.teleprompt import Teleprompter from dspy.teleprompt.utils import ( + create_minibatch, create_n_fewshot_demo_sets, eval_candidate_program, get_program_with_highest_avg_score, @@ -19,9 +20,10 @@ print_full_program, save_candidate_program, set_signature, - create_minibatch, ) +logger = logging.getLogger(__name__) + # Constants BOOTSTRAPPED_FEWSHOT_EXAMPLES_IN_CONTEXT = 3 LABELED_FEWSHOT_EXAMPLES_IN_CONTEXT = 0 @@ -148,7 +150,7 @@ def compile( valset, program_aware_proposer, ): - print("Compilation aborted by the user.") + logger.info("Compilation aborted by the user.") return student # Return the original student program # Initialize program and evaluator @@ -248,7 +250,7 @@ def _set_and_validate_datasets(self, trainset: List, valset: Optional[List]): return trainset, valset def _print_auto_run_settings(self, num_trials: int, minibatch: bool, valset: List): - print( + logger.info( f"\nRUNNING WITH THE FOLLOWING {self.auto.upper()} AUTO RUN SETTINGS:" f"\nnum_trials: {num_trials}" f"\nminibatch: {minibatch}" @@ -359,24 +361,24 @@ def _get_user_confirmation( """ ) - print(user_message) - sys.stdout.flush() - print(user_confirmation_message) - user_input = input("Do you wish to continue? (y/n): ").strip().lower() + user_input = input( + f"{user_message}\n{user_confirmation_message}\n" + "Do you wish to continue? (y/n): " + ).strip().lower() return user_input == "y" def _bootstrap_fewshot_examples( self, program: Any, trainset: List, seed: int ) -> Optional[List]: - print("\n==> STEP 1: BOOTSTRAP FEWSHOT EXAMPLES <==") + logger.info("\n==> STEP 1: BOOTSTRAP FEWSHOT EXAMPLES <==") if self.max_bootstrapped_demos > 0: - print( + logger.info( "These will be used as few-shot example candidates for our program and for creating instructions.\n" ) else: - print("These will be used for informing instruction proposal.\n") + logger.info("These will be used for informing instruction proposal.\n") - print(f"Bootstrapping N={self.num_candidates} sets of demonstrations...") + logger.info(f"Bootstrapping N={self.num_candidates} sets of demonstrations...") zeroshot = self.max_bootstrapped_demos == 0 and self.max_labeled_demos == 0 @@ -403,8 +405,8 @@ def _bootstrap_fewshot_examples( rng=self.rng, ) except Exception as e: - print(f"Error generating few-shot examples: {e}") - print("Running without few-shot examples.") + logger.info(f"Error generating few-shot examples: {e}") + logger.info("Running without few-shot examples.") demo_candidates = None return demo_candidates @@ -420,8 +422,8 @@ def _propose_instructions( tip_aware_proposer: bool, fewshot_aware_proposer: bool, ) -> Dict[int, List[str]]: - print("\n==> STEP 2: PROPOSE INSTRUCTION CANDIDATES <==") - print( + logger.info("\n==> STEP 2: PROPOSE INSTRUCTION CANDIDATES <==") + logger.info( "We will use the few-shot examples from the previous step, a generated dataset summary, a summary of the program code, and a randomly selected prompting tip to propose instructions." ) @@ -441,7 +443,7 @@ def _propose_instructions( rng=self.rng ) - print("\nProposing instructions...\n") + logger.info("\nProposing instructions...\n") instruction_candidates = proposer.propose_instructions_for_program( trainset=trainset, program=program, @@ -452,11 +454,11 @@ def _propose_instructions( ) for i, pred in enumerate(program.predictors()): - print(f"Proposed Instructions for Predictor {i}:\n") + logger.info(f"Proposed Instructions for Predictor {i}:\n") instruction_candidates[i][0] = get_signature(pred).instructions for j, instruction in enumerate(instruction_candidates[i]): - print(f"{j}: {instruction}\n") - print("\n") + logger.info(f"{j}: {instruction}\n") + logger.info("\n") return instruction_candidates @@ -473,9 +475,9 @@ def _optimize_prompt_parameters( minibatch_full_eval_steps: int, seed: int, ) -> Optional[Any]: - print("Evaluating the default program...\n") + logger.info("Evaluating the default program...\n") default_score = eval_candidate_program(len(valset), valset, program, evaluate, self.rng) - print(f"Default program score: {default_score}\n") + logger.info(f"Default program score: {default_score}\n") # Initialize optimization variables best_score = default_score @@ -496,9 +498,9 @@ def objective(trial): trial_num = trial.number + 1 if minibatch: - print(f"== Minibatch Trial {trial_num} / {num_trials} ==") + logger.info(f"== Minibatch Trial {trial_num} / {num_trials} ==") else: - print(f"===== Trial {trial_num} / {num_trials} =====") + logger.info(f"===== Trial {trial_num} / {num_trials} =====") trial_logs[trial_num] = {} @@ -517,7 +519,7 @@ def objective(trial): # Log assembled program if self.verbose: - print("Evaluating the following candidate program...\n") + logger.info("Evaluating the following candidate program...\n") print_full_program(candidate_program) # Save the candidate program @@ -535,7 +537,7 @@ def objective(trial): if not minibatch and score > best_score: best_score = score best_program = candidate_program.deepcopy() - print(f"{GREEN}Best full score so far!{ENDC} Score: {score}") + logger.info(f"{GREEN}Best full score so far!{ENDC} Score: {score}") # Log evaluation results scores.append(score) @@ -587,8 +589,8 @@ def objective(trial): # Run optimization optuna.logging.set_verbosity(optuna.logging.WARNING) - print("==> STEP 3: FINDING OPTIMAL PROMPT PARAMETERS <==") - print( + logger.info("==> STEP 3: FINDING OPTIMAL PROMPT PARAMETERS <==") + logger.info( "We will evaluate the program over a series of trials with different combinations of instructions and few-shot examples to find the optimal combination using Bayesian Optimization.\n" ) @@ -603,7 +605,7 @@ def objective(trial): best_program.prompt_model_total_calls = self.prompt_model_total_calls best_program.total_calls = self.total_calls - print(f"Returning best identified program with score {best_score}!") + logger.info(f"Returning best identified program with score {best_score}!") return best_program @@ -618,24 +620,24 @@ def _log_minibatch_eval( trial, num_trials, ): - print( + logger.info( f"Score: {score} on minibatch of size {batch_size} with parameters {chosen_params}." ) - print(f"Minibatch scores so far: {'['+', '.join([f'{s}' for s in scores])+']'}") + logger.info(f"Minibatch scores so far: {'['+', '.join([f'{s}' for s in scores])+']'}") trajectory = "[" + ", ".join([f"{s}" for s in full_eval_scores]) + "]" - print(f"Full eval scores so far: {trajectory}") - print(f"Best full score so far: {best_score}") - print( + logger.info(f"Full eval scores so far: {trajectory}") + logger.info(f"Best full score so far: {best_score}") + logger.info( f'{"="*len(f"== Minibatch Trial {trial.number+1} / {num_trials} ==")}\n\n' ) def _log_normal_eval( self, score, best_score, chosen_params, scores, trial, num_trials ): - print(f"Score: {score} with parameters {chosen_params}.") - print(f"Scores so far: {'['+', '.join([f'{s}' for s in scores])+']'}") - print(f"Best score so far: {best_score}") - print(f'{"="*len(f"===== Trial {trial.number+1} / {num_trials} =====")}\n\n') + logger.info(f"Score: {score} with parameters {chosen_params}.") + logger.info(f"Scores so far: {'['+', '.join([f'{s}' for s in scores])+']'}") + logger.info(f"Best score so far: {best_score}") + logger.info(f'{"="*len(f"===== Trial {trial.number+1} / {num_trials} =====")}\n\n') def _select_and_insert_instructions_and_demos( self, @@ -685,7 +687,7 @@ def _perform_full_evaluation( best_score: float, best_program: Any, ): - print(f"===== Full Eval {len(fully_evaled_param_combos)+1} =====") + logger.info(f"===== Full Eval {len(fully_evaled_param_combos)+1} =====") # Identify best program to evaluate fully highest_mean_program, mean_score, combo_key = ( @@ -693,7 +695,7 @@ def _perform_full_evaluation( param_score_dict, fully_evaled_param_combos ) ) - print( + logger.info( f"Doing full eval on next top averaging program (Avg Score: {mean_score}) from minibatch trials..." ) full_eval_score = eval_candidate_program( @@ -719,13 +721,13 @@ def _perform_full_evaluation( # Update best score and program if necessary if full_eval_score > best_score: - print(f"{GREEN}New best full eval score!{ENDC} Score: {full_eval_score}") + logger.info(f"{GREEN}New best full eval score!{ENDC} Score: {full_eval_score}") best_score = full_eval_score best_program = highest_mean_program.deepcopy() trajectory = "[" + ", ".join([f"{s}" for s in full_eval_scores]) + "]" - print(f"Full eval scores so far: {trajectory}") - print(f"Best full score so far: {best_score}") - print(len(f"===== Full Eval {len(fully_evaled_param_combos)+1} =====") * "=") - print("\n") + logger.info(f"Full eval scores so far: {trajectory}") + logger.info(f"Best full score so far: {best_score}") + logger.info(len(f"===== Full Eval {len(fully_evaled_param_combos)+1} =====") * "=") + logger.info("\n") return best_score, best_program diff --git a/dspy/utils/__init__.py b/dspy/utils/__init__.py index bff180328..f16061eb8 100644 --- a/dspy/utils/__init__.py +++ b/dspy/utils/__init__.py @@ -1,3 +1,3 @@ from dspy.utils.callback import BaseCallback, with_callbacks from dspy.utils.dummies import * -from dspy.utils.logging import * +from dspy.utils.logging_utils import * diff --git a/dspy/utils/logging.py b/dspy/utils/logging.py deleted file mode 100644 index a2fa66680..000000000 --- a/dspy/utils/logging.py +++ /dev/null @@ -1,100 +0,0 @@ -import logging -import os -import sys -import typing as t - -import structlog - -logger = structlog.get_logger() - - -class LogSettings: - def __init__(self, output_type: str, method: str, file_name: t.Optional[str]) -> None: - self.output_type = output_type - self.method = method - self.file_name = file_name - self._configure_structlog() - - def _configure_structlog(self): - if self.output_type == "str": - renderer = structlog.dev.ConsoleRenderer() - else: - renderer = structlog.processors.JSONRenderer() - - structlog.configure( - processors=[ - structlog.stdlib.add_logger_name, - structlog.stdlib.add_log_level, - structlog.processors.CallsiteParameterAdder( - { - structlog.processors.CallsiteParameter.FILENAME, - structlog.processors.CallsiteParameter.LINENO, - }, - ), - structlog.processors.TimeStamper(fmt="iso"), - structlog.processors.StackInfoRenderer(), - structlog.processors.format_exc_info, - structlog.processors.UnicodeDecoder(), - renderer, - ], - logger_factory=structlog.stdlib.LoggerFactory(), - wrapper_class=structlog.stdlib.BoundLogger, - ) - - def set_log_output( - self, - method: t.Optional[str] = None, - file_name: t.Optional[str] = None, - output_type: t.Optional[str] = None, - ): - if method is not None and method not in ["console", "file"]: - raise ValueError("method provided can only be 'console', 'file'") - - if method == "file" and file_name is None: - raise ValueError("file_name must be provided when method = 'file'") - - if method is not None: - self.method = method - self.file_name = file_name - - if output_type is not None and output_type not in ["str", "json"]: - raise ValueError("output_type provided can only be 'str', 'json'") - - if output_type is not None: - self.output_type = output_type - - # Update Renderer - self._configure_structlog() - - # Grab the root logger - log = logging.getLogger() - for handler in log.handlers[:]: - log.removeHandler(handler) - - # Add new Handler - if self.method == "file": - assert self.file_name is not None - log.addHandler(logging.FileHandler(self.file_name)) - else: - log.addHandler(logging.StreamHandler(sys.stdout)) - - -level = os.environ.get("LOG_LEVEL", "info").upper() - - -# Set Defaults -def show_logging(level: str = level) -> None: - logging.basicConfig( - format="%(message)s", - stream=sys.stdout, - level=level, - ) - - # 'backoff' is used by OpenAI, and defaults their log level to INFO. - # this can clobber up dspy relevant logging for users - # this silences there logs. - logging.getLogger("backoff").setLevel(logging.WARNING) - - -settings = LogSettings(output_type="str", method="console", file_name=None) -set_log_output = settings.set_log_output diff --git a/dspy/utils/logging_utils.py b/dspy/utils/logging_utils.py new file mode 100644 index 000000000..c6b62e027 --- /dev/null +++ b/dspy/utils/logging_utils.py @@ -0,0 +1,83 @@ +import logging +import logging.config +import sys + +LOGGING_LINE_FORMAT = "%(asctime)s %(levelname)s %(name)s: %(message)s" +LOGGING_DATETIME_FORMAT = "%Y/%m/%d %H:%M:%S" + + +class DSPyLoggingStream: + """ + A Python stream for use with event logging APIs throughout DSPy (`eprint()`, + `logger.info()`, etc.). This stream wraps `sys.stderr`, forwarding `write()` and + `flush()` calls to the stream referred to by `sys.stderr` at the time of the call. + It also provides capabilities for disabling the stream to silence event logs. + """ + + def __init__(self): + self._enabled = True + + def write(self, text): + if self._enabled: + sys.stderr.write(text) + + def flush(self): + if self._enabled: + sys.stderr.flush() + + @property + def enabled(self): + return self._enabled + + @enabled.setter + def enabled(self, value): + self._enabled = value + + +DSPY_LOGGING_STREAM = DSPyLoggingStream() + + +def disable_logging(): + """ + Disables the `DSPyLoggingStream` used by event logging APIs throughout DSPy + (`eprint()`, `logger.info()`, etc), silencing all subsequent event logs. + """ + DSPY_LOGGING_STREAM.enabled = False + + +def enable_logging(): + """ + Enables the `DSPyLoggingStream` used by event logging APIs throughout DSPy + (`eprint()`, `logger.info()`, etc), emitting all subsequent event logs. This + reverses the effects of `disable_logging()`. + """ + DSPY_LOGGING_STREAM.enabled = True + + +def configure_dspy_loggers(root_module_name): + logging.config.dictConfig( + { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "dspy_formatter": { + "format": LOGGING_LINE_FORMAT, + "datefmt": LOGGING_DATETIME_FORMAT, + }, + }, + "handlers": { + "dspy_handler": { + "formatter": "dspy_formatter", + "class": "logging.StreamHandler", + "stream": DSPY_LOGGING_STREAM, + }, + }, + "loggers": { + root_module_name: { + "handlers": ["dspy_handler"], + "level": "INFO", + "propagate": False, + }, + }, + } + )