diff --git a/.env.template b/.env.template index 84d8ba84..ebe7fa16 100644 --- a/.env.template +++ b/.env.template @@ -8,6 +8,7 @@ # Application Settings # ============================================================================= LOG_LEVEL=INFO +PERFORMANCE_LOG_FORMAT=compact # compact|rich # SESSION_OBSERVERS_LIMIT=10 # GET_CONTEXT_MAX_TOKENS=100000 # MAX_FILE_SIZE=5242880 # Bytes diff --git a/config.toml.example b/config.toml.example index 9e0e9c11..54bf1ffd 100644 --- a/config.toml.example +++ b/config.toml.example @@ -6,6 +6,7 @@ # Application-level settings [app] LOG_LEVEL = "INFO" +PERFORMANCE_LOG_FORMAT = "compact" # "compact" for single-line logs, "rich" for local panels SESSION_OBSERVERS_LIMIT = 10 GET_CONTEXT_MAX_TOKENS = 100000 MAX_FILE_SIZE = 5242880 # 5MB diff --git a/src/config.py b/src/config.py index fa700d6d..5a0e3937 100644 --- a/src/config.py +++ b/src/config.py @@ -1353,6 +1353,7 @@ class AppSettings(HonchoSettings): # Application-wide settings LOG_LEVEL: str = "INFO" + PERFORMANCE_LOG_FORMAT: str = "compact" SESSION_OBSERVERS_LIMIT: Annotated[int, Field(default=10, gt=0)] = 10 MAX_FILE_SIZE: Annotated[int, Field(default=5_242_880, gt=0)] = 5_242_880 # 5MB GET_CONTEXT_MAX_TOKENS: Annotated[int, Field(default=100_000, gt=0, le=250_000)] = ( @@ -1401,6 +1402,13 @@ class AppSettings(HonchoSettings): raise ValueError(f"Invalid log level: {v}") return log_level + @field_validator("PERFORMANCE_LOG_FORMAT") + def validate_performance_log_format(cls, v: str) -> str: + log_format = v.lower() + if log_format not in ["compact", "rich"]: + raise ValueError(f"Invalid performance log format: {v}") + return log_format + @model_validator(mode="after") def propagate_namespace(self) -> "AppSettings": """Propagate top-level NAMESPACE to nested settings if not explicitly set.""" diff --git a/src/crud/document.py b/src/crud/document.py index 018f3411..11eb121d 100644 --- a/src/crud/document.py +++ b/src/crud/document.py @@ -1024,8 +1024,10 @@ async def is_rejected_duplicate( # If new document has more or equal information, keep it and delete existing if score_new >= score_existing: - logger.warning( - f"[DUPLICATE DETECTION] Deleting existing in favor of new. new='{doc.content}', existing='{existing_doc.content}'." + logger.debug( + "[DUPLICATE DETECTION] Deleting existing in favor of new. new=%r, existing=%r.", + doc.content, + existing_doc.content, ) # Carry the reinforcement count forward so replacing a duplicate counts as # another derivation rather than resetting times_derived to 1. @@ -1041,8 +1043,10 @@ async def is_rejected_duplicate( # reinforcing the same document must not lose updates. existing_doc.times_derived = models.Document.times_derived + 1 await db.flush() - logger.warning( - f"[DUPLICATE DETECTION] Rejecting new in favor of existing. new='{doc.content}', existing='{existing_doc.content}'." + logger.debug( + "[DUPLICATE DETECTION] Rejecting new in favor of existing. new=%r, existing=%r.", + doc.content, + existing_doc.content, ) return True diff --git a/src/deriver/enqueue.py b/src/deriver/enqueue.py index aaeda415..05883306 100644 --- a/src/deriver/enqueue.py +++ b/src/deriver/enqueue.py @@ -495,7 +495,7 @@ async def enqueue_dream( is_in_progress = await db_session.scalar(in_progress_check) if is_in_progress: - logger.info( + logger.debug( "Skipping dream enqueue - already in progress: %s/%s/%s (type: %s)", workspace_name, observer, @@ -515,7 +515,7 @@ async def enqueue_dream( is_pending = await db_session.scalar(pending_check) if is_pending: - logger.info( + logger.debug( "Dream already pending in queue: %s/%s/%s (type: %s)", workspace_name, observer, diff --git a/src/dreamer/dream_scheduler.py b/src/dreamer/dream_scheduler.py index bad850f4..43bba428 100644 --- a/src/dreamer/dream_scheduler.py +++ b/src/dreamer/dream_scheduler.py @@ -218,7 +218,7 @@ class DreamScheduler: configuration = get_configuration(None, session, workspace) if not configuration.dream.enabled: - logger.info( + logger.debug( f"Dreams disabled for {workspace_name}/{session_name}, skipping dream" ) return @@ -319,7 +319,7 @@ async def check_and_schedule_dream( ).total_seconds() / 3600 if hours_since_last_dream < settings.DREAM.MIN_HOURS_BETWEEN_DREAMS: - logger.info( + logger.debug( f"Skipping dream for {collection.observer}/{collection.observed}: only {hours_since_last_dream:.1f} hours " + f"since last dream (minimum: {settings.DREAM.MIN_HOURS_BETWEEN_DREAMS})" ) @@ -359,7 +359,7 @@ async def check_and_schedule_dream( ) ) if pending_exists: - logger.info( + logger.debug( "Skipping dream schedule for %s/%s: pending dream already in queue", collection.observer, collection.observed, diff --git a/src/reconciler/scheduler.py b/src/reconciler/scheduler.py index d4f314a3..e171c4fa 100644 --- a/src/reconciler/scheduler.py +++ b/src/reconciler/scheduler.py @@ -264,5 +264,5 @@ class ReconcilerScheduler: ) return False - logger.info("Enqueued reconciler task: %s", task.name) + logger.debug("Enqueued reconciler task: %s", task.name) return True diff --git a/src/reconciler/sync_vectors.py b/src/reconciler/sync_vectors.py index cdc18542..68e9ac59 100644 --- a/src/reconciler/sync_vectors.py +++ b/src/reconciler/sync_vectors.py @@ -728,7 +728,7 @@ async def run_vector_reconciliation_cycle() -> ReconciliationMetrics: if not (embs_work or cleanup_work): break - logger.info("Vector reconciliation cycle completed (pgvector mode)") + logger.debug("Vector reconciliation cycle completed (pgvector mode)") return metrics # External vector store mode - reconcile documents, embeddings, and cleanup @@ -755,5 +755,5 @@ async def run_vector_reconciliation_cycle() -> ReconciliationMetrics: logger.debug("No work done, breaking reconciliation loop") break - logger.info("Vector reconciliation cycle completed") + logger.debug("Vector reconciliation cycle completed") return metrics diff --git a/src/telemetry/logging.py b/src/telemetry/logging.py index c2fcba69..441b1f96 100644 --- a/src/telemetry/logging.py +++ b/src/telemetry/logging.py @@ -17,7 +17,6 @@ from rich.console import Console, Group, RenderableType from rich.panel import Panel from rich.table import Table from rich.text import Text -from rich.tree import Tree from src.config import settings from src.telemetry.metrics_collector import append_metrics_to_file @@ -176,28 +175,6 @@ def format_reasoning_inputs_as_markdown( return "\n".join(parts) -def log_representation( - representation: Representation, -) -> None: - """ - Log representation in a tree structure. - Args: - representation: Representation to log - """ - tree = Tree("📊 REPRESENTATION") - - type_branch = tree.add(f"[bold cyan]EXPLICIT[/] ({len(representation.explicit)})") - for i, obs in enumerate(representation.explicit, 1): - type_branch.add(f"[dim]{i}.[/] {obs}") - - type_branch = tree.add(f"[bold cyan]DEDUCTIVE[/] ({len(representation.deductive)})") - for i, obs in enumerate(representation.deductive, 1): - type_branch.add(f"[dim]{i}.[/] {obs}") - - console.print(tree) - console.print() - - def accumulate_metric( task_name: str, label: str, @@ -276,16 +253,20 @@ def log_performance_metrics( task_slug: str, task_name: str, metrics: list[tuple[str, str | int | float, str]] | None = None, - title: str = "⚡ PERFORMANCE", + title: str = "PERFORMANCE", ) -> None: """ - Log performance metrics in a clean table and optionally send to global collector. + Log performance metrics and optionally send them to the global collector. + + PERFORMANCE_LOG_FORMAT=compact emits numeric metrics on one INFO line and + keeps large "blob" metrics at DEBUG. PERFORMANCE_LOG_FORMAT=rich prints the + local Rich panel, including blob metrics, for interactive readability. Args: task_slug: Slug of the task that generated these metrics task_name: Name of the task that generated these metrics - metrics: Dictionary of metric names and (value, unit) tuples - title: Table title + metrics: List of (metric_name, value, unit) tuples + title: Prefix for the log line """ task_name = f"{task_slug}_{task_name}" # No-op if metrics were evicted (due to MAX_ACCUMULATED_TASKS limit) and no @@ -300,7 +281,41 @@ def log_performance_metrics( if COLLECT_METRICS_LOCAL: append_metrics_to_file(task_slug, task_name, metrics) - # Remove metrics with "blob" unit type. They get printed separately below the table. + if settings.PERFORMANCE_LOG_FORMAT == "rich": + _log_performance_metrics_rich(task_name, metrics, title) + return + + # Keep large text payloads out of the compact INFO summary. + blob_metrics: list[tuple[str, str | int | float, str]] = [] + summary_parts: list[str] = [] + for metric, value, unit in metrics: + if unit == "blob": + blob_metrics.append((metric, value, unit)) + continue + if unit == "ms" and isinstance(value, int | float): + formatted_value = f"{value:.0f}ms" + elif unit == "s" and isinstance(value, int | float): + formatted_value = f"{value:.3f}s" + elif unit in ("", "tokens", "count", "id"): + formatted_value = str(value) + else: + formatted_value = f"{value}{unit}" + summary_parts.append(f"{metric}={formatted_value}") + + if summary_parts: + logger.info("%s %s | %s", title, task_name, " | ".join(summary_parts)) + else: + logger.info("%s %s", title, task_name) + + for metric, value, _unit in blob_metrics: + logger.debug("%s %s :: %s\n%s", title, task_name, metric, value) + + +def _log_performance_metrics_rich( + task_name: str, + metrics: list[tuple[str, str | int | float, str]], + title: str, +) -> None: blob_metrics: list[tuple[str, str | int | float, str]] = [] non_blob_metrics: list[tuple[str, str | int | float, str]] = [] for metric in metrics: @@ -317,24 +332,20 @@ def log_performance_metrics( table.add_column("Unit", style="dim", width=8) for metric, value, unit in non_blob_metrics: - if unit == "ms": + if unit == "ms" and isinstance(value, int | float): formatted_value = f"{value:.0f}" - elif unit == "s": + elif unit == "s" and isinstance(value, int | float): formatted_value = f"{value:.3f}" else: formatted_value = str(value) table.add_row(metric.replace("_", " ").title(), formatted_value, unit) - # Build content for the panel content_items: list[RenderableType] = [table] - if blob_metrics: - for metric, value, _unit in blob_metrics: - content_items.append( - Text.assemble(" ", (f"\n{metric}:", "bold"), " ") - ) - content_items.append(Text(str(value))) + for metric, value, _unit in blob_metrics: + content_items.append(Text.assemble(" ", (f"\n{metric}:", "bold"), " ")) + content_items.append(Text(str(value))) panel = Panel( Group(*content_items),