diff --git a/pyproject.toml b/pyproject.toml index 5177c5a5..4d581b42 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -26,6 +26,7 @@ dependencies = [ "blinker>=1.8.2", "python-telegram-bot>=21.0", "html2markdown>=0.1.7", + "loguru>=0.7.2", ] [project.urls] diff --git a/src/bub/channels/manager.py b/src/bub/channels/manager.py index f2414d8f..bec86d01 100644 --- a/src/bub/channels/manager.py +++ b/src/bub/channels/manager.py @@ -5,6 +5,8 @@ import asyncio from collections.abc import Callable, Iterable +from loguru import logger + from bub.app.runtime import AppRuntime from bub.channels.base import BaseChannel from bub.channels.bus import MessageBus @@ -34,10 +36,12 @@ async def start(self) -> None: self._loop = asyncio.get_running_loop() self._unsub_inbound = self.bus.on_inbound(self._handle_inbound) self._unsub_outbound = self.bus.on_outbound(self._handle_outbound) + logger.info("channel.manager.start channels={}", sorted(self._channels.keys())) for channel in self._channels.values(): self._tasks.append(asyncio.create_task(channel.start())) async def stop(self) -> None: + logger.info("channel.manager.stop") for channel in self._channels.values(): await channel.stop() for task in self._tasks: @@ -83,10 +87,17 @@ async def _process_inbound(self, message: InboundMessage) -> None: ) async def _process_outbound(self, message: OutboundMessage) -> None: - channel = self._channels.get(message.channel) - if channel is None: - return - await channel.send(message) + try: + channel = self._channels.get(message.channel) + if channel is None: + return + await channel.send(message) + except Exception: + logger.exception( + "channel.outbound.error channel={} chat_id={}", + message.channel, + message.chat_id, + ) def enabled_channels(self) -> Iterable[str]: return self._channels.keys() diff --git a/src/bub/channels/telegram.py b/src/bub/channels/telegram.py index d40887a0..45267d94 100644 --- a/src/bub/channels/telegram.py +++ b/src/bub/channels/telegram.py @@ -5,6 +5,7 @@ import asyncio from dataclasses import dataclass +from loguru import logger from telegram import Update from telegram.ext import Application, CommandHandler, ContextTypes, MessageHandler, filters @@ -35,6 +36,7 @@ def __init__(self, bus: MessageBus, config: TelegramConfig) -> None: async def start(self) -> None: if not self._config.token: raise RuntimeError("telegram token is empty") + logger.info("telegram.channel.start allow_from_count={}", len(self._config.allow_from)) self._running = True self._app = Application.builder().token(self._config.token).build() self._app.add_handler(CommandHandler("start", self._on_start)) @@ -46,6 +48,7 @@ async def start(self) -> None: if updater is None: return await updater.start_polling(drop_pending_updates=True, allowed_updates=["message"]) + logger.info("telegram.channel.polling") while self._running: await asyncio.sleep(0.5) @@ -62,6 +65,7 @@ async def stop(self) -> None: await self._app.stop() await self._app.shutdown() self._app = None + logger.info("telegram.channel.stopped") async def send(self, message: OutboundMessage) -> None: if self._app is None: @@ -127,4 +131,5 @@ async def _typing_loop(self, chat_id: str) -> None: except asyncio.CancelledError: return except Exception: + logger.exception("telegram.channel.typing_loop.error chat_id={}", chat_id) return diff --git a/src/bub/cli/app.py b/src/bub/cli/app.py index 2a45d5ba..59d08ed4 100644 --- a/src/bub/cli/app.py +++ b/src/bub/cli/app.py @@ -7,10 +7,12 @@ from typing import Annotated import typer +from loguru import logger from bub.app import build_runtime from bub.channels import ChannelManager, MessageBus, TelegramChannel, TelegramConfig from bub.cli.interactive import InteractiveCli +from bub.logging_utils import configure_logging app = typer.Typer(name="bub", help="Tape-first coding agent CLI", add_completion=False) TELEGRAM_DISABLED_ERROR = "telegram is disabled; set BUB_TELEGRAM_ENABLED=true" @@ -31,7 +33,15 @@ def chat( ) -> None: """Run interactive CLI.""" - runtime = build_runtime(workspace or Path.cwd(), model=model, max_tokens=max_tokens) + configure_logging(profile="chat") + resolved_workspace = (workspace or Path.cwd()).resolve() + logger.info( + "chat.start workspace={} model={} max_tokens={}", + str(resolved_workspace), + model or "", + max_tokens if max_tokens is not None else "", + ) + runtime = build_runtime(resolved_workspace, model=model, max_tokens=max_tokens) InteractiveCli(runtime).run() @@ -43,11 +53,22 @@ def telegram( ) -> None: """Run Telegram adapter with the same agent loop runtime.""" - runtime = build_runtime(workspace or Path.cwd(), model=model, max_tokens=max_tokens) + configure_logging() + resolved_workspace = (workspace or Path.cwd()).resolve() + logger.info( + "telegram.start workspace={} model={} max_tokens={}", + str(resolved_workspace), + model or "", + max_tokens if max_tokens is not None else "", + ) + + runtime = build_runtime(resolved_workspace, model=model, max_tokens=max_tokens) token = runtime.settings.telegram_token if not runtime.settings.telegram_enabled: + logger.error("telegram.disabled workspace={}", str(resolved_workspace)) raise typer.BadParameter(TELEGRAM_DISABLED_ERROR) if not token: + logger.error("telegram.missing_token workspace={}", str(resolved_workspace)) raise typer.BadParameter(TELEGRAM_TOKEN_ERROR) bus = MessageBus() @@ -64,13 +85,21 @@ def telegram( try: asyncio.run(_serve_channels(manager)) except KeyboardInterrupt: - return + logger.info("telegram.interrupted") + except Exception: + logger.exception("telegram.crash") + raise + finally: + logger.info("telegram.stop workspace={}", str(resolved_workspace)) async def _serve_channels(manager: ChannelManager) -> None: + channels = sorted(manager.enabled_channels()) + logger.info("channels.start enabled={}", channels) await manager.start() try: while True: await asyncio.sleep(1.0) finally: await manager.stop() + logger.info("channels.stop") diff --git a/src/bub/cli/interactive.py b/src/bub/cli/interactive.py index 5ba0ddc2..5f340284 100644 --- a/src/bub/cli/interactive.py +++ b/src/bub/cli/interactive.py @@ -12,7 +12,7 @@ from prompt_toolkit.history import FileHistory from prompt_toolkit.key_binding import KeyBindings from prompt_toolkit.patch_stdout import patch_stdout -from rich.console import Console +from rich import get_console from bub.app.runtime import AppRuntime from bub.cli.render import CliRenderer @@ -25,7 +25,7 @@ def __init__(self, runtime: AppRuntime, *, session_id: str = "cli") -> None: self._runtime = runtime self._session_id = session_id self._session = runtime.get_session(session_id) - self._renderer = CliRenderer(Console()) + self._renderer = CliRenderer(get_console()) self._mode = "agent" self._prompt = self._build_prompt() diff --git a/src/bub/core/model_runner.py b/src/bub/core/model_runner.py index f0c9cefa..5b738312 100644 --- a/src/bub/core/model_runner.py +++ b/src/bub/core/model_runner.py @@ -9,6 +9,7 @@ from dataclasses import dataclass, field from typing import Callable +from loguru import logger from republic import StructuredOutput from bub.core.router import AssistantRouteResult, InputRouter @@ -162,6 +163,7 @@ def _worker() -> None: ) result_queue.put(_ChatResult.from_structured(output)) except Exception as exc: + logger.exception("model.call.error") result_queue.put(_ChatResult(text="", error=f"model_call_error: {exc!s}")) thread = threading.Thread(target=_worker, daemon=True, name="bub-model-call") diff --git a/src/bub/logging_utils.py b/src/bub/logging_utils.py new file mode 100644 index 00000000..58c13b97 --- /dev/null +++ b/src/bub/logging_utils.py @@ -0,0 +1,59 @@ +"""Runtime logging helpers.""" + +from __future__ import annotations + +import os +import sys +from logging import Handler +from typing import Literal + +from loguru import logger +from rich import get_console +from rich.logging import RichHandler + +LogProfile = Literal["default", "chat"] + +_PROFILE_FORMATS: dict[LogProfile, str] = { + "chat": "{level} | {message}", + "default": "{time:YYYY-MM-DD HH:mm:ss.SSS} | {level:<8} | {name}:{function}:{line} | {message}", +} +_CONFIGURED_PROFILE: LogProfile | None = None + + +def _build_chat_handler() -> Handler: + return RichHandler( + console=get_console(), + show_level=True, + show_time=False, + show_path=False, + markup=False, + rich_tracebacks=False, + ) + + +def configure_logging(*, profile: LogProfile = "default") -> None: + """Configure process-level logging once.""" + + global _CONFIGURED_PROFILE + if profile == _CONFIGURED_PROFILE: + return + + level = os.getenv("BUB_LOG_LEVEL", "INFO").upper() + logger.remove() + if profile == "chat": + logger.add( + _build_chat_handler(), + level=level, + format="{message}", + backtrace=False, + diagnose=False, + ) + else: + logger.add( + sys.stderr, + level=level, + format=_PROFILE_FORMATS[profile], + backtrace=False, + diagnose=False, + ) + _CONFIGURED_PROFILE = profile diff --git a/src/bub/tools/builtin.py b/src/bub/tools/builtin.py index 50dfda14..29ba707a 100644 --- a/src/bub/tools/builtin.py +++ b/src/bub/tools/builtin.py @@ -3,7 +3,6 @@ from __future__ import annotations import json -import shlex import shutil import subprocess from pathlib import Path @@ -544,9 +543,3 @@ def _skill_handler(_params: EmptyInput, *, skill_name: str = skill.name) -> str: source="skill", ) ) - - -def shell_cmd_from_tokens(tokens: list[str]) -> str: - """Return shell command string preserving token quoting.""" - - return " ".join(shlex.quote(token) for token in tokens) diff --git a/src/bub/tools/registry.py b/src/bub/tools/registry.py index 88e18a85..0c4bcf23 100644 --- a/src/bub/tools/registry.py +++ b/src/bub/tools/registry.py @@ -3,9 +3,12 @@ from __future__ import annotations import builtins +import textwrap +import time from dataclasses import dataclass from typing import Any +from loguru import logger from republic import Tool, ToolContext @@ -58,6 +61,14 @@ def detail(self, name: str) -> str: f"schema: {schema}" ) + def _log_tool_call(self, name: str, kwargs: dict[str, Any], context: ToolContext | None) -> None: + params: list[str] = [] + for key, value in kwargs.items(): + value = textwrap.shorten(str(value), width=30, placeholder="...") + params.append(f"{key}={value}") + params_str = ", ".join(params) + logger.info("tool.call.start name={} {{ {} }}", name, params_str) + def execute( self, name: str, @@ -69,6 +80,15 @@ def execute( if descriptor is None: raise KeyError(name) - if descriptor.tool.context: - return descriptor.tool.run(context=context, **kwargs) - return descriptor.tool.run(**kwargs) + self._log_tool_call(name, kwargs, context) + start = time.monotonic() + try: + if descriptor.tool.context: + return descriptor.tool.run(context=context, **kwargs) + return descriptor.tool.run(**kwargs) + except Exception: + logger.exception("tool.call.error name={}", name) + raise + finally: + duration = time.monotonic() - start + logger.info("tool.call.end name={} duration={:.3f}ms", name, duration * 1000) diff --git a/uv.lock b/uv.lock index 491cf58b..5abab66d 100644 --- a/uv.lock +++ b/uv.lock @@ -75,6 +75,7 @@ source = { editable = "." } dependencies = [ { name = "blinker" }, { name = "html2markdown" }, + { name = "loguru" }, { name = "prompt-toolkit" }, { name = "pydantic" }, { name = "pydantic-settings" }, @@ -103,6 +104,7 @@ dev = [ requires-dist = [ { name = "blinker", specifier = ">=1.8.2" }, { name = "html2markdown", specifier = ">=0.1.7" }, + { name = "loguru", specifier = ">=0.7.2" }, { name = "prompt-toolkit", specifier = ">=3.0.0" }, { name = "pydantic", specifier = ">=2.0.0" }, { name = "pydantic-settings", specifier = ">=2.0.0" }, @@ -350,6 +352,19 @@ wheels = [ { url = "https://files.pythonhosted.org/packages/b3/4a/4175a563579e884192ba6e81725fc0448b042024419be8d83aa8a80a3f44/jiter-0.10.0-cp314-cp314t-manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:3aa96f2abba33dc77f79b4cf791840230375f9534e5fac927ccceb58c5e604a5", size = 354213, upload-time = "2025-05-18T19:04:41.894Z" }, ] +[[package]] +name = "loguru" +version = "0.7.3" +source = { registry = "https://pypi.org/simple" } +dependencies = [ + { name = "colorama", marker = "sys_platform == 'win32'" }, + { name = "win32-setctime", marker = "sys_platform == 'win32'" }, +] +sdist = { url = "https://files.pythonhosted.org/packages/3a/05/a1dae3dffd1116099471c643b8924f5aa6524411dc6c63fdae648c4f1aca/loguru-0.7.3.tar.gz", hash = "sha256:19480589e77d47b8d85b2c827ad95d49bf31b0dcde16593892eb51dd18706eb6", size = 63559, upload-time = "2024-12-06T11:20:56.608Z" } +wheels = [ + { url = "https://files.pythonhosted.org/packages/0c/29/0348de65b8cc732daa3e33e67806420b2ae89bdce2b04af740289c5c6c8c/loguru-0.7.3-py3-none-any.whl", hash = "sha256:31a33c10c8e1e10422bfd431aeb5d351c7cf7fa671e3c4df004162264b28220c", size = 61595, upload-time = "2024-12-06T11:20:54.538Z" }, +] + [[package]] name = "markdown" version = "3.8.2" @@ -1133,3 +1148,12 @@ sdist = { url = "https://files.pythonhosted.org/packages/c2/62/a7c072fbfefb2980a wheels = [ { url = "https://files.pythonhosted.org/packages/3c/c1/d73f12f8cdb1891334a2ccf7389eed244d3941e74d80dd220badb937f3fb/wcwidth-0.5.3-py3-none-any.whl", hash = "sha256:d584eff31cd4753e1e5ff6c12e1edfdb324c995713f75d26c29807bb84bf649e", size = 92981, upload-time = "2026-01-31T03:52:09.14Z" }, ] + +[[package]] +name = "win32-setctime" +version = "1.2.0" +source = { registry = "https://pypi.org/simple" } +sdist = { url = "https://files.pythonhosted.org/packages/b3/8f/705086c9d734d3b663af0e9bb3d4de6578d08f46b1b101c2442fd9aecaa2/win32_setctime-1.2.0.tar.gz", hash = "sha256:ae1fdf948f5640aae05c511ade119313fb6a30d7eabe25fef9764dca5873c4c0", size = 4867, upload-time = "2024-12-07T15:28:28.314Z" } +wheels = [ + { url = "https://files.pythonhosted.org/packages/e1/07/c6fe3ad3e685340704d314d765b7912993bcb8dc198f0e7a89382d37974b/win32_setctime-1.2.0-py3-none-any.whl", hash = "sha256:95d644c4e708aba81dc3704a116d8cbc974d70b3bdb8be1d150e36be6e9d1390", size = 4083, upload-time = "2024-12-07T15:28:26.465Z" }, +]