feat: add logs

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]

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()

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

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 "<default>",
+        max_tokens if max_tokens is not None else "<default>",
+    )
+    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 "<default>",
+        max_tokens if max_tokens is not None else "<default>",
+    )
+
+    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")

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()
 

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")

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

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)

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)