feat: add structured logging and DEBUG flag

README.md

@@ -39,6 +39,8 @@ uv run --frozen weather-briefing run hourly
 
 `LLM_PROVIDER=deepseek` 使用 `DEEPSEEK_API_KEY`、`DEEPSEEK_MODEL` 和可选的 `DEEPSEEK_BASE_URL`；DeepSeek provider 已预置官方 Base URL。`LLM_PROVIDER=openai-compatible` 使用 `LLM_API_KEY`、`LLM_MODEL` 和 `LLM_BASE_URL`。两套配置互不回退。
 
+应用将带时间、级别和 logger 名称的运行日志写入标准错误；设置 `DEBUG=true` 可输出 RSS 获取和 LLM 重试等诊断信息。
+
 定位层从地名解析国家或行政区代码。Open-Meteo 负责城市/邮编查询，空结果时由 OpenStreetMap Nominatim 解析详细地名；结果会持久缓存。只有坐标时使用中国大陆服务范围四至宽松包围盒作快速可能性判断。省略 `WEATHER_PROVIDERS` 时，中国大陆地点使用 QWeather、Open-Meteo，其他地点只使用 Open-Meteo；显式配置时首项是主要来源，后续项依次作为备用。
 
 RSS 为可选补充数据。需要使用时复制 `rss-sources.example.json` 为被 Git 忽略的 `rss-sources.json` 并填写真实来源；不创建该文件即可只使用天气 API。

docs/design.md

@@ -85,6 +85,8 @@ SQLite 没有原生日期时间类型，状态存储需要直接对 TEXT 做范
 
 小时 LLM 结果包含布尔字段 `should_publish`。模型比较当前及历史 API 快照，仅在降雨、显著天气变化、预警或灾害动态值得打扰时设为真；活动预警不允许与 false 同时出现。false 结果不投递消息，但当前快照、文章去重和预警状态仍持久化。
 
+CLI 在读取运行配置前以 INFO 幂等配置单个标准错误 handler，配置成功后再按 `DEBUG` 更新级别，避免配置错误绕过统一格式、daemon 每轮任务重复追加 handler 或向 root logger 重复传播。默认记录生命周期、文章数量、陈旧来源和失败信息；`DEBUG` 启用 RSS 获取及 LLM 重试诊断。业务层只给异常追加失败计数等上下文，完整堆栈由 CLI 入口或 APScheduler 单点记录。
+
 ## 依赖边界
 
 运行时只保留各自承担单一职责的直接依赖：APScheduler 负责进程内定时调度，Beautiful Soup 负责不可信 HTML 的 DOM 清洗，feedparser 负责 RSS/Atom 解析，HTTPX 负责异步 HTTP 与可选 SOCKS 代理，Pendulum 负责时区感知时间和日历运算，python-dotenv 负责自托管环境的本地配置加载。PyJWT 的 `crypto` extra 是唯一的加密接口，QWeather 认证只调用它的高层 EdDSA JWT 编码 API，不直接调用底层加密原语。异步测试使用 AnyIO 自带的 pytest plugin，在 Python 3.11–3.14 上采用 asyncio backend，不额外引入事件循环插件。项目不引入模型厂商、天气厂商、Telegram SDK 或运行时类型检查框架，以免把可替换边界绑定到额外工具。

env.example

@@ -17,6 +17,8 @@ LLM_MAX_ATTEMPTS=3
 
 # Optional HTTP tuning.
 HTTP_TIMEOUT_SECONDS=30
+# Set to true for verbose application diagnostics. Logs are written to stderr.
+DEBUG=false
 
 # Required: a private JSON file containing one or more locations. Each object
 # requires id and name; latitude and longitude are an optional pair. If omitted,

tests/test_cli.py

@@ -1,21 +1,61 @@
+import logging
 from pathlib import Path
 
 import pendulum
 import pytest
 
 from weather_briefing.cli import (
+    _LOGGER,
+    _configure_logging,
     _hour_in_cron,
     _in_schedule,
     _location_state_path,
     _parse_run_time,
     _precision_reduction_notice,
     build_parser,
     main,
+    run,
 )
 from weather_briefing.config import Settings
 from weather_briefing.models import ResolvedLocation
 
 
+def test_configure_logging_is_idempotent_and_updates_level() -> None:
+    original_handlers = _LOGGER.handlers[:]
+    original_level = _LOGGER.level
+    original_propagate = _LOGGER.propagate
+    original_root_handlers = logging.root.handlers[:]
+    original_root_level = logging.root.level
+    original_httpx_level = logging.getLogger("httpx").level
+    original_httpcore_level = logging.getLogger("httpcore").level
+    try:
+        _LOGGER.handlers.clear()
+        logging.root.handlers.clear()
+
+        _configure_logging(debug=False)
+        own_handler = _LOGGER.handlers[0]
+        root_handler = logging.root.handlers[0]
+        _configure_logging(debug=True)
+
+        assert _LOGGER.handlers == [own_handler]
+        assert _LOGGER.level == logging.DEBUG
+        assert not _LOGGER.propagate
+        assert logging.root.handlers == [root_handler]
+        assert logging.root.level == logging.DEBUG
+        assert logging.getLogger("httpx").level == logging.WARNING
+        assert logging.getLogger("httpcore").level == logging.WARNING
+    finally:
+        _LOGGER.handlers.clear()
+        _LOGGER.handlers.extend(original_handlers)
+        _LOGGER.setLevel(original_level)
+        _LOGGER.propagate = original_propagate
+        logging.root.handlers.clear()
+        logging.root.handlers.extend(original_root_handlers)
+        logging.root.setLevel(original_root_level)
+        logging.getLogger("httpx").setLevel(original_httpx_level)
+        logging.getLogger("httpcore").setLevel(original_httpcore_level)
+
+
 @pytest.mark.parametrize(
     "value",
     ("2026-03-29T02:30:00", "2026-10-25T02:30:00"),
@@ -156,3 +196,245 @@ def fake_load_dotenv(*, override: bool) -> bool:
 
     assert exc_info.value.code == 0
     assert calls == [False]
+
+
+def test_main_configures_info_logging_before_daemon_and_logs_failure_once(monkeypatch, capsys) -> None:
+    original_handlers = _LOGGER.handlers[:]
+    original_level = _LOGGER.level
+    original_propagate = _LOGGER.propagate
+    original_root_handlers = logging.root.handlers[:]
+    original_root_level = logging.root.level
+
+    async def fail_daemon(run_now: bool = False) -> None:
+        assert len(_LOGGER.handlers) == 1
+        assert _LOGGER.level == logging.INFO
+        raise RuntimeError("daemon-boom")
+
+    monkeypatch.setattr("weather_briefing.cli.load_dotenv", lambda *, override: True)
+    monkeypatch.setattr("weather_briefing.cli.daemon", fail_daemon)
+    monkeypatch.setattr("sys.argv", ["weather-briefing", "daemon"])
+    try:
+        _LOGGER.handlers.clear()
+        logging.root.handlers.clear()
+
+        with pytest.raises(SystemExit) as exc_info:
+            main()
+
+        stderr = capsys.readouterr().err
+        assert exc_info.value.code == 1
+        assert stderr.count("weather-briefing terminated with an error") == 1
+        assert stderr.count("RuntimeError: daemon-boom") == 1
+        assert "[ERROR] weather_briefing:" in stderr
+    finally:
+        _LOGGER.handlers.clear()
+        _LOGGER.handlers.extend(original_handlers)
+        _LOGGER.setLevel(original_level)
+        _LOGGER.propagate = original_propagate
+        logging.root.handlers.clear()
+        logging.root.handlers.extend(original_root_handlers)
+        logging.root.setLevel(original_root_level)
+
+
+def test_main_configures_info_logging_before_run_and_logs_failure_once(monkeypatch, capsys) -> None:
+    original_handlers = _LOGGER.handlers[:]
+    original_level = _LOGGER.level
+    original_propagate = _LOGGER.propagate
+    original_root_handlers = logging.root.handlers[:]
+    original_root_level = logging.root.level
+
+    async def fail_run(kind: str, enforce_window: bool, at: str | None) -> None:
+        assert kind == "hourly"
+        assert not enforce_window
+        assert at is None
+        assert len(_LOGGER.handlers) == 1
+        assert _LOGGER.level == logging.INFO
+        raise RuntimeError("boom")
+
+    monkeypatch.setattr("weather_briefing.cli.load_dotenv", lambda *, override: True)
+    monkeypatch.setattr("weather_briefing.cli.run", fail_run)
+    monkeypatch.setattr("sys.argv", ["weather-briefing", "run", "hourly"])
+    try:
+        _LOGGER.handlers.clear()
+        logging.root.handlers.clear()
+
+        with pytest.raises(SystemExit) as exc_info:
+            main()
+
+        stderr = capsys.readouterr().err
+        assert exc_info.value.code == 1
+        assert stderr.count("weather-briefing terminated with an error") == 1
+        assert stderr.count("RuntimeError: boom") == 1
+        assert "[ERROR] weather_briefing:" in stderr
+    finally:
+        _LOGGER.handlers.clear()
+        _LOGGER.handlers.extend(original_handlers)
+        _LOGGER.setLevel(original_level)
+        _LOGGER.propagate = original_propagate
+        logging.root.handlers.clear()
+        logging.root.handlers.extend(original_root_handlers)
+        logging.root.setLevel(original_root_level)
+
+
+def _make_fake_settings(**overrides: object) -> object:
+    from types import SimpleNamespace
+
+    tz = pendulum.timezone("Asia/Shanghai")
+    defaults: dict[str, object] = {
+        "debug": False,
+        "timezone": tz,
+        "api_key": "k",
+        "llm_provider": "deepseek",
+        "llm_model": "m",
+        "llm_base_url": None,
+        "llm_max_output_tokens": 8192,
+        "llm_max_attempts": 3,
+        "http_timeout_seconds": 30,
+        "locations": (),
+        "locations_path": Path("locations.json"),
+        "geocoding_base_url": "https://geo.example.com",
+        "geocoding_api_key": None,
+        "nominatim_base_url": "https://nominatim.example.com",
+        "geocoding_user_agent": "test",
+        "geocoding_cache_path": Path("state/geocoding.json"),
+        "feeds": (),
+        "context_sources": (),
+        "weather_providers": None,
+        "qweather_project_id": None,
+        "qweather_credential_id": None,
+        "qweather_private_key": None,
+        "qweather_jwt_lifetime_seconds": 900,
+        "qweather_base_url": None,
+        "qweather_index_types": (),
+        "open_meteo_weather_base_url": "https://weather.example.com",
+        "open_meteo_air_quality_base_url": "https://air.example.com",
+        "open_meteo_api_key": None,
+        "aqicn_api_token": None,
+        "aqicn_base_url": "https://aqi.example.com",
+        "state_path": Path("state/weather.sqlite3"),
+        "publisher": "stdout",
+        "telegram_bot_token": None,
+        "telegram_chat_id": None,
+        "rss_max_attempts": 3,
+        "rss_retry_min_seconds": 3,
+        "rss_retry_max_seconds": 5,
+        "rss_stale_hours": 24,
+        "task_failure_threshold": 3,
+        "warning_retention_hours": 12,
+        "history_hours": 48,
+        "briefing_max_characters": 3500,
+        "greeting_hour": 8,
+        "greeting_minute": 0,
+        "hourly_cron": "9-23",
+    }
+    defaults.update(overrides)
+    return SimpleNamespace(**defaults)
+
+
+class _FakeAsyncClient:
+    def __init__(self) -> None:
+        self.timeout = None
+
+    async def __aenter__(self) -> "_FakeAsyncClient":
+        return self
+
+    async def __aexit__(self, *args: object) -> None:
+        pass
+
+
+async def test_run_skips_and_logs_when_enforce_window_outside_schedule(monkeypatch, capsys) -> None:
+    from unittest.mock import patch
+
+    settings = _make_fake_settings(debug=False)
+    tz = pendulum.timezone("Asia/Shanghai")
+    now = pendulum.datetime(2026, 7, 14, 3, tz=tz)
+
+    original_handlers = _LOGGER.handlers[:]
+    original_level = _LOGGER.level
+    original_propagate = _LOGGER.propagate
+    original_root_handlers = logging.root.handlers[:]
+    original_root_level = logging.root.level
+    try:
+        _LOGGER.handlers.clear()
+        logging.root.handlers.clear()
+
+        monkeypatch.setattr("weather_briefing.cli._parse_run_time", lambda v, t: now)
+        monkeypatch.setattr("weather_briefing.cli._in_schedule", lambda k, n, s: False)
+        with patch.object(Settings, "from_env", classmethod(lambda cls: settings)):
+            await run("hourly", enforce_window=True)
+
+        stderr = capsys.readouterr().err
+        assert "Skipping delayed hourly run outside configured local-time window" in stderr
+        assert "[INFO] weather_briefing:" in stderr
+    finally:
+        _LOGGER.handlers.clear()
+        _LOGGER.handlers.extend(original_handlers)
+        _LOGGER.setLevel(original_level)
+        _LOGGER.propagate = original_propagate
+        logging.root.handlers.clear()
+        logging.root.handlers.extend(original_root_handlers)
+        logging.root.setLevel(original_root_level)
+
+
+async def test_run_logs_start_resolve_and_publish(monkeypatch, capsys) -> None:
+    from types import SimpleNamespace
+    from unittest.mock import patch
+
+    from weather_briefing.models import ResolvedLocation
+
+    tz = pendulum.timezone("Asia/Shanghai")
+    now = pendulum.datetime(2026, 7, 14, 8, tz=tz)
+    location = ResolvedLocation("test", "Test City", 39.9, 116.3, "CN", "Beijing", tz.name, True)
+    settings = _make_fake_settings(debug=False, publisher="stdout", locations=(location,))
+
+    monkeypatch.setattr("weather_briefing.cli._parse_run_time", lambda v, t: now)
+    monkeypatch.setattr("weather_briefing.cli._in_schedule", lambda k, n, s: True)
+    monkeypatch.setattr("weather_briefing.cli._delivery_provider", lambda s, c: None)
+    monkeypatch.setattr("weather_briefing.cli._llm_provider", lambda s, c: None)
+    monkeypatch.setattr("weather_briefing.cli._weather_context_provider", lambda s, c, loc: None)
+    monkeypatch.setattr("weather_briefing.cli.httpx.AsyncClient", lambda **kw: _FakeAsyncClient())
+
+    class FakeResolver:
+        async def resolve_with_metadata(self, loc: object) -> object:
+            return SimpleNamespace(location=loc, from_cache=True)
+
+    monkeypatch.setattr("weather_briefing.cli.CachedLocationResolver", lambda *a, **kw: FakeResolver())
+
+    class FakeState:
+        def __enter__(self) -> "FakeState":
+            return self
+
+        def __exit__(self, *args: object) -> None:
+            pass
+
+    monkeypatch.setattr("weather_briefing.cli.SQLiteStateStore", lambda p: FakeState())
+
+    async def fake_service_run(kind: str, n: object) -> str:
+        return "published body"
+
+    monkeypatch.setattr("weather_briefing.cli.BriefingService", lambda *a, **kw: SimpleNamespace(run=fake_service_run))
+
+    original_handlers = _LOGGER.handlers[:]
+    original_level = _LOGGER.level
+    original_propagate = _LOGGER.propagate
+    original_root_handlers = logging.root.handlers[:]
+    original_root_level = logging.root.level
+    try:
+        _LOGGER.handlers.clear()
+        logging.root.handlers.clear()
+
+        with patch.object(Settings, "from_env", classmethod(lambda cls: settings)):
+            await run("hourly", enforce_window=False)
+
+        stderr = capsys.readouterr().err
+        assert "Starting hourly briefing run" in stderr
+        assert "Resolving 1 location(s)" in stderr
+        assert "Processing location test (Test City)" in stderr
+        assert "briefing published (14 characters)" in stderr
+    finally:
+        _LOGGER.handlers.clear()
+        _LOGGER.handlers.extend(original_handlers)
+        _LOGGER.setLevel(original_level)
+        _LOGGER.propagate = original_propagate
+        logging.root.handlers.clear()
+        logging.root.handlers.extend(original_root_handlers)
+        logging.root.setLevel(original_root_level)

tests/test_config.py

@@ -211,6 +211,14 @@ def test_env_value_with_unmatched_quotes_is_unchanged(monkeypatch, value: str) -
     assert settings.api_key == value
 
 
+@pytest.mark.parametrize("value", ("1", "true", "yes", "'true'", '"yes"'))
+def test_debug_accepts_truthy_values_with_optional_outer_quotes(monkeypatch, value: str) -> None:
+    _required_environment(monkeypatch)
+    monkeypatch.setenv("DEBUG", value)
+
+    assert Settings.from_env().debug
+
+
 @pytest.mark.parametrize(
     "name",
     (

tests/test_service.py

@@ -342,8 +342,9 @@ async def test_failure_alert_is_sent_only_when_threshold_is_first_reached(
             delivery,
         )
         for attempt in range(4):
-            with pytest.raises(RuntimeError, match="feed unavailable"):
+            with pytest.raises(RuntimeError, match="feed unavailable") as error:
                 await service.run("hourly", now.add(hours=attempt))
+            assert error.value.__notes__ == [f"Briefing run failed after {attempt + 1} consecutive failure(s)"]
 
     assert len(publisher.messages) == 1
     assert "连续失败 3 次" in publisher.messages[0][0].body