Python / logging
===
###### tags: `Python`
###### tags: `Python`, `logging`

<br>

[TOC]

<br>

## 範例程式
### 範例1

import logging

print('>'*20 + 'print')
logging.debug('>'*20 + 'debug')
logging.info('>'*20 + 'info')
logging.warning('>'*20 + 'warning')
logging.error('>'*20 + 'error')
logging.critical('>'*20 + 'critical')

執行結果：

<br>

### 範例2
> https://docs.python.org/zh-tw/3/howto/logging.html#displaying-the-date-time-in-messages

import logging
logging.basicConfig(format='[%(asctime)s][%(levelname)s] %(message)s', datefmt='%Y-%m-%d %H:%M:%S')
ogging.warning('is when this event was logged.')

執行結果：

[2022-09-23 16:01:21][WARNING] is when this event was logged.

<br>

### 範例3

import logging
logging.basicConfig(format='[%(asctime)s][%(levelname)s][%(pathname)s][%(filename)s][%(module)s][%(funcName)s][%(lineno)s] %(message)s', datefmt='%Y-%m-%d %H:%M:%S')
logging.warning('here is a demo message)

> [2022-09-23 16:34:35][WARNING][/tmp/ipykernel_76557/294564305.py][294564305.py][294564305][<module>][3] here is a demo message

- [How to log source file name and line number in Python](https://stackoverflow.com/a/533077/4359712)

<br>

### 範例4：更新 logger level
> 使用情境：jupyterlab / notebook

import logging
import traceback

logger = logging.getLogger()
current_level = logger.getEffectiveLevel()
print('getLevelName:', logging.getLevelName(current_level))

logger.setLevel(level=logging.DEBUG)

logger = logging.getLogger()
current_level = logger.getEffectiveLevel()
print('getLevelName:', logging.getLevelName(current_level))

try:
    x = 5/0
except Exception as e:
    print(e)
    print('-' * 60)
    print(traceback.format_exc())
    print('-' * 60)
    logging.info("Failed!!")
    print('-' * 60)
    logging.info("Failed!!", exc_info=True)


<br>

### 範例5：在 class 裡初始化 logger

import logging

class MyService:
    def __init__(self):
        self.logger = logging.getLogger(self.__class__.__name__)
        self.logger.setLevel(logging.DEBUG)  # 確保這支 logger 本身允許 DEBUG

⚠️ 但注意：
- **就算 logger 設成 DEBUG，如果沒有 handler 或 root handler 的 level 太高，
一樣不會出現 log**。
- 所以通常還是要在程式入口用 `basicConfig(...)` 設一次。

<br>

## API
### [`logging.debug(msg, *args, **kwargs)`](https://docs.python.org/zh-tw/3/library/logging.html#logging.debug)

<br>

## 教學文件
- [如何使用 Logging 模組](https://docs.python.org/zh-tw/3/howto/logging.html)

<br>

<hr>

<br>

## 進階設定：彩色 logging
> 

> - ✅ 終極 Logging Utility 範本
> - 這是一份模組化 logging utility，具備你要的功能：
> - ✅ 功能一覽
> - 支援 console + file 同時輸出
> - 彩色 console log（等級顏色區分）
> - Log 檔案自動輪替（`RotatingFileHandler`）
> - 可整合 Pydantic `Settings`

### logging_config.py

import logging
import sys
from logging.handlers import RotatingFileHandler
from pathlib import Path
from typing import Optional


class ColorFormatter(logging.Formatter):
    """彩色的 log formatter，CLI 用起來比較爽。"""

    COLORS = {
        "DEBUG": "\033[36m",     # 青色
        "INFO": "\033[32m",      # 綠色
        "WARNING": "\033[33m",   # 黃色
        "ERROR": "\033[31m",     # 紅色
        "CRITICAL": "\033[41m",  # 紅底白字
    }
    RESET = "\033[0m"

    def format(self, record: logging.LogRecord) -> str:
        level_color = self.COLORS.get(record.levelname, "")
        reset = self.RESET if level_color else ""
        msg = super().format(record)
        return f"{level_color}{msg}{reset}"


def configure_logging(
    name: str = "SyncPilot",
    level: int = logging.INFO,
    log_file: Optional[Path] = None,
    log_to_console: bool = True,
    max_bytes: int = 5 * 1024 * 1024,
    backup_count: int = 3,
) -> logging.Logger:
    """
    Configure logger with optional file and colored console.

    Parameters
    ----------
    name : str
        Logger name.
    level : int
        Log level (e.g., logging.DEBUG).
    log_file : Path, optional
        Path to the log file. If None, no file logging.
    log_to_console : bool
        Whether to log to stdout.
    max_bytes : int
        Max file size before rotation.
    backup_count : int
        How many rotated logs to keep.

    Returns
    -------
    logging.Logger
        Configured logger instance.
    """
    logger = logging.getLogger(name)
    logger.setLevel(level)
    logger.propagate = False  # 防止重複 log

    formatter = logging.Formatter(
        fmt="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
        datefmt="%Y-%m-%d %H:%M:%S"
    )

    # Console log with color
    if log_to_console and not any(
        isinstance(h, logging.StreamHandler) for h in logger.handlers
    ):
        ch = logging.StreamHandler(sys.stdout)
        ch.setLevel(level)
        ch.setFormatter(ColorFormatter(
            fmt="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
            datefmt="%H:%M:%S"
        ))
        logger.addHandler(ch)

    # File log with rotation
    if log_file and not any(
        isinstance(h, RotatingFileHandler) for h in logger.handlers
    ):
        fh = RotatingFileHandler(
            log_file, maxBytes=max_bytes, backupCount=backup_count,
            encoding="utf-8"
        )
        fh.setLevel(level)
        fh.setFormatter(formatter)
        logger.addHandler(fh)

    return logger

<br>

### settings.py

# settings.py
from pydantic_settings import BaseSettings
from typing import Literal
import logging
from pathlib import Path


class Settings(BaseSettings):
    APP_NAME: str = "SyncPilot"
    LOGGING_LEVEL: Literal[
        "DEBUG", "INFO", "WARNING", "ERROR"
    ] = "DEBUG"
    LOG_FILE: Path = Path("syncpilot.log")

    @property
    def logging_level(self) -> int:
        return {
            "DEBUG": logging.DEBUG,
            "INFO": logging.INFO,
            "WARNING": logging.WARNING,
            "ERROR": logging.ERROR,
        }.get(self.LOGGING_LEVEL, logging.INFO)


settings = Settings()

<br>

### main.py

# main.py
from logging_config import configure_logging
from settings import settings

logger = configure_logging(
    name=settings.APP_NAME,
    level=settings.logging_level,
    log_file=settings.LOG_FILE,
    log_to_console=True
)

logger.debug("Debug message")
logger.info("Application started.")
logger.warning("Warning issued.")
logger.error("Something went wrong.")

### 執行結果

<br>

<hr>

<br>

## 討論
### python 中，要用 debug flag 來控制更詳細的 log，以及輸出 warning log，通常要如何做？
[ChatGPT]
在 Python 中，你可以使用內建的 `logging` 模組來實現日誌記錄，並透過設定不同的日誌等級來控制詳細程度。 以下是一個簡單的例子，示範如何根據 debug 標誌以及輸出 warning 資訊：

import logging

def setup_logging(debug=False):
     logging.basicConfig(level=logging.DEBUG if debug else logging.INFO,
                         format='%(asctime)s - %(levelname)s - %(message)s')

def main():
     debug_flag = True # 設定為 True 表示開啟詳細日誌記錄
     setup_logging(debug=debug_flag)

     logging.debug("This is a debug message.")
     logging.info("This is an info message.")
     logging.warning("This is a warning message.")

if __name__ == "__main__":
     main()

在這個範例中，我們使用 `setup_logging` 函數來初始化日誌記錄配置。 透過將 `debug` 參數設為 `True`，我們開啟了 DEBUG 等級的日誌記錄，這將輸出更詳細的資訊。 如果將 `debug` 參數設為 `False`，則僅輸出 INFO 等級及以上的日誌。

你可以根據需要調整日誌級別，包括 `DEBUG`、`INFO`、`WARNING`、`ERROR` 和 `CRITICAL`。

<br>

### level=logging.DEBUG，為何設過一次後，就無法在變更 level ？
[ChatGPT]
在使用 basicConfig 進行配置的情況下，一旦配置完成，就無法再次變更其配置。 這是因為 basicConfig 只應該在應用程式的早期階段呼叫一次，以配置根記錄器。

如果你想要動態變更記錄器的配置，可以使用 getLogger 取得記錄器對象，然後為其設定處理程序、格式等。 例如：

import logging

# 在應用程式的早期階段進行一次配置
logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(levelname)s - %(message)s')

# 取得根記錄器
logger = logging.getLogger()

# 動態變更記錄器的 level
logger.setLevel(logging.DEBUG)

# 新增處理程序、設定格式等
# handler = logging.StreamHandler()
# formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
# handler.setFormatter(formatter)
# logger.addHandler(handler)

# 現在可以使用 logger.debug("...") 輸出 DEBUG 等級的日誌

這樣就可以在運行時動態更改日誌等級和進行其他配置。

- 參考資料
- [Get Output From the logging Module in IPython Notebook](https://stackoverflow.com/questions/18786912/)

<br>

### 如何查看當前 logging 套件的 level 是 INFO ? VERBOSE?
[ChatGPT]
在 Python 中，您可以使用 `logging` 模組的 `getLogger` 方法來取得一個日誌記錄器（logger），然後使用該記錄器的 `getEffectiveLevel` 方法來查看目前的日誌等級。 以下是一個範例，展示如何檢查預設記錄器（root logger）的目前日誌等級：

import logging

# 取得預設記錄器
logger = logging.getLogger()

# 取得並列印目前日誌等級
current_level = logger.getEffectiveLevel()
print("目前日誌等級:", logging.getLevelName(current_level))

這段程式碼會列印出目前日誌層級的名稱，如 `INFO`、`DEBUG` 等。 請注意，日誌等級是以整數形式儲存的，`getEffectiveLevel` 方法傳回的是這個整數值。 `logging.getLevelName` 函數可以將這個整數轉換為對應的等級名稱。

如果您想檢查特定記錄器的日誌級別，只需在 `getLogger` 方法中傳入該記錄器的名稱即可。 例如：

Copy code
# 取得名為'my_logger'的記錄器的日誌級別
my_logger = logging.getLogger('my_logger')
current_level = my_logger.getEffectiveLevel()
print("目前日誌等級:", logging.getLevelName(current_level))

請注意，`VERBOSE` 並不是 Python 標準 `logging` 模組的一個預先定義日誌等級。 如果您在應用程式中看到了 `VERBOSE` 級別，這可能是自訂級別或由第三方程式庫添加的。 您可以檢查應用程式的配置或程式碼，看看是否定義了這樣的自訂等級。 如果是，您可能需要查看該程式庫或套用的文件來了解如何檢索該層級的資訊。

<br>

### 使用 Python logging 套件，想要加上檔名，logging 要如何使用？
- ### gpt-4o (2025/04/17)
你可以在設定 `logging` 時，加上 `format` 格式字串，讓 log 訊息中顯示目前執行的 **檔名 (module)**，方法如下：

### ✅ 建議用法：加入 `%(filename)s`

    import logging

    logging.basicConfig(
        level=logging.DEBUG,
        format='%(asctime)s [%(levelname)s] %(filename)s: %(message)s',
    )

### 🔍 格式參考

| 格式符號 | 說明 |
|----------------|----------------------------|
| `%(asctime)s` | 時間戳記 |
| `%(levelname)s`| 日誌等級（DEBUG, INFO 等） |
| `%(filename)s` | 執行此 log 的 Python 檔名 |
| `%(lineno)d` | 執行此 log 的 Python 檔名 |
| `%(message)s` | 真正的 log 內容 |

---

### 🧪 範例輸出：

    2025-04-17 14:08:22,114 [DEBUG] my_script.py: Contents of zip file: [...]

如果你想加上行號，可以用 `%(lineno)d`：

    format='%(asctime)s [%(levelname)s] %(filename)s:%(lineno)d - %(message)s'

需要我幫你加上 log formatter 給 `uvicorn` 或 FastAPI 也能用嗎？

<br>

### `logging.basicConfig()` 是每個檔案設定一次，還是入口點所在程式設定就好？
- ### gpt-4o (2025/04/17)
### ✅ 正確做法：
通常 **只需要在「入口點」的程式設定一次 `logging.basicConfig()`** 就好。

---

### 🔧 詳細說明：

- `logging.basicConfig()` 是全域設定，全程只會生效一次（第一次呼叫時）。
- 一旦設定完成，其他模組只要用 `logging.getLogger(__name__)` 或直接用 `logging.debug/info/warning()` 就會依照該設定運作。
- **不需要每個檔案都設定 `basicConfig()`**，這樣反而可能導致設定失效或重複。

---

### 📁 範例架構：

    project/
    ├── main.py         ← 入口點，這裡設定 logging
    ├── utils/
    │   └── helper.py   ← 只需使用 logging，不用再設定 basicConfig

#### main.py

    import logging
    from utils import helper

    logging.basicConfig(
        level=logging.DEBUG,
        format='%(asctime)s [%(levelname)s] %(filename)s: %(message)s'
    )

    helper.do_something()

#### utils/helper.py

    import logging

    def do_something():
        logging.info("Helper is working!")

---

### 🚫 錯誤用法：
- 每個檔案都呼叫 `basicConfig()`
- 👉 會造成只有第一個呼叫的地方生效，其他不會覆蓋

---

如你是用 FastAPI + Uvicorn，還可以加強控制 log formatter 和 handler，要我幫你示範嗎？

<br>

### 為什麼 `logging.basicConfig()` 在 FastAPI 中無效？
- ### gpt-4o (2025/04/17)
這個問題的核心是：**`uvicorn` 自帶的 log 設定會「搶先」載入並主控 log 行為**，導致你在 `main.py` 裡的 `logging.basicConfig(...)` 不生效。

---

### 🔍 為什麼 `basicConfig()` 沒生效？

因為 Python 的 `logging.basicConfig()` **只會對第一次設定生效**。而當你用 `uvicorn` 執行 FastAPI app 時，它會在載入 app 之前就先設定好 log handler。

所以你後面再呼叫 `basicConfig()` 根本不會改變現有的 log 設定。

---

### ✅ 解法 1：使用 `force=True`（Python 3.8+）

讓 `basicConfig()` 強制重設所有 logging handler。

    logging.basicConfig(
        level=logging.DEBUG,
        format='%(asctime)s [%(levelname)s] %(filename)s: %(message)s',
        force=True
    )

✔ 這是最簡單也最推薦的方式，但需要 Python 3.8 以上。

---

### ✅ 解法 2：自己定義 root logger 與 handler（不靠 `basicConfig`）

    import logging

    logger = logging.getLogger()
    logger.setLevel(logging.DEBUG)

    # 移除 uvicorn 預設 handler（避免重複）
    for handler in logger.handlers[:]:
        logger.removeHandler(handler)

    # 自訂 handler
    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.DEBUG)
    console_handler.setFormatter(logging.Formatter(
        '%(asctime)s [%(levelname)s] %(filename)s: %(message)s'
    ))

    logger.addHandler(console_handler)

---

### ✅ 補充：如果你用 `uvicorn main:app` 啟動，可以加上 `--log-config` 或調整 log level：

    uvicorn main:app --reload --log-level debug

---

需要我幫你整合進 FastAPI 專案的最佳 log 設定範本嗎？包含 uvicorn + 自訂 logger？

<br>

### Python Logging 設定與 FastAPI 整合使用者資訊
- ### gpt-4o (2025/04/17)
### ✅ 基本 logging 設定

設定時間戳記（asctime）、log 等級、檔名與行號：

    import logging

    logging.basicConfig(
        level=logging.DEBUG,
        format='%(asctime)s [%(levelname)s] %(filename)s:%(lineno)d - %(message)s',
        datefmt='%Y/%m/%d %H:%M:%S',
    )

輸出範例：

    2025/04/17 14:20:10 [DEBUG] zip_handler.py:45 - Contents of zip file: [...]

---

### ✅ 進階版：整合 FastAPI，加入 IP、Token、使用者 ID

#### 步驟 1：定義 ContextVar 儲存用戶資訊

    from contextvars import ContextVar

    log_context = ContextVar("log_context", default={})

---

### 步驟 2：定義自訂 Formatter 加入使用者資訊

    class ContextAwareFormatter(logging.Formatter):
        def format(self, record):
            context = log_context.get({})
            record.user = context.get("user", "unknown")
            record.ip = context.get("ip", "unknown")
            record.token = context.get("token", "none")
            return super().format(record)

---

### 步驟 3：設置 logging handler 與格式

    formatter = ContextAwareFormatter(
        fmt='%(asctime)s [%(levelname)s] [user:%(user)s ip:%(ip)s token:%(token)s] %(filename)s:%(lineno)d - %(message)s',
        datefmt='%Y/%m/%d %H:%M:%S'
    )

    handler = logging.StreamHandler()
    handler.setFormatter(formatter)

    logger = logging.getLogger()
    logger.setLevel(logging.DEBUG)
    logger.handlers = [handler]

---

### 步驟 4：在 FastAPI 加入 Middleware 注入 log context

    from fastapi import FastAPI, Request

    app = FastAPI()

    @app.middleware("http")
    async def inject_log_context(request: Request, call_next):
        ip = request.client.host
        token = request.headers.get("authorization", "none")
        user = request.headers.get("x-user-id", "guest")

        log_context.set({
            "ip": ip,
            "token": token,
            "user": user,
        })

        return await call_next(request)

---

### 🧪 實際使用

    logger.info("收到 ZIP 檔案，開始解壓縮...")

輸出範例：

    2025/04/17 14:25:12 [INFO] [user:admin ip:127.0.0.1 token:Bearer xyz...] file_upload.py:88 - 收到 ZIP 檔案，開始解壓縮...

---

如需將 log 輸出到檔案並每日輪替，可使用 `TimedRotatingFileHandler`，若需要請告知我。

<br>

---
---

<br>

## 討論 - 看不到 log 的問題
### 有執行 `logger.debug()`，卻看不到 log
- ### Question

    self.logger.debug(f"Get user list (offset={offset}, limit={limit})")

我要如何設定 logger 才能讓 log 印出來？現在我看不到 log
- ### gpt-5.2 (2026/01/29)
你這行是 `debug` 等級：

    self.logger.debug(f"Get user list (offset={offset}, limit={limit})")

**看不到的最常見原因**：logger 的等級還停在 `INFO`（或更高），所以 `DEBUG` 被過濾掉了。你只要把 **logger / handler / root logger** 的 level 設成 `DEBUG`，並確保有 handler 輸出到 console，就會印出來。

---

### 最小可用範例（建議先用這個確認）

在程式進入點（例如 `main.py`、FastAPI 的啟動檔）最一開始加：

    import logging

    logging.basicConfig(
        level=logging.DEBUG,
        format="%(asctime)s %(levelname)s %(name)s: %(message)s",
    )

    logger = logging.getLogger(__name__)
    logger.debug("debug will show")

只要這段有印出來，你的環境就 OK 了。

---

### 你現在是 `self.logger`：推薦這樣初始化

在 class / module 裡：

    import logging

    class MyService:
        def __init__(self):
            self.logger = logging.getLogger(self.__class__.__name__)
            self.logger.setLevel(logging.DEBUG)  # 確保這支 logger 本身允許 DEBUG

⚠️ 但注意：**就算 logger 設成 DEBUG，如果沒有 handler 或 root handler 的 level 太高，一樣不會出現**。所以通常還是要在程式入口用 `basicConfig(...)` 設一次。

---

### 如果你是跑 FastAPI / Uvicorn

Uvicorn 預設可能不是 debug，請用：

    uvicorn main:app --log-level debug

或在程式裡維持 `logging.basicConfig(level=logging.DEBUG, ...)`，兩種都可。

---

### 常見坑（你可以快速檢查）

1. **你有呼叫 `basicConfig` 嗎？**（而且要在第一次 import/初始化 logging 之前）
2. **是不是被別的地方先設定過 logging？**
`basicConfig()` 只在「第一次設定」有效，若已經有人加過 handler，它可能不會改你想要的設定。
3. **handler 等級太高**（例如 handler 是 INFO，logger 是 DEBUG 也沒用）
4. **在 pytest 內**：pytest 會捕捉 log，需加 `-s` 或設定 `--log-cli-level=DEBUG`

---

如果你願意貼一下你目前的 logger 初始化（`self.logger` 是怎麼建立的、程式入口怎麼啟動的、是否用 uvicorn/gunicorn/pytest），我可以直接指出是哪個點把 `DEBUG` 擋掉。

<br>

---

<br>

### 為什麼設定 `logging.basicConfig()` 後，還是沒生效？
- ### 前言
- jupyterlab/noteebook 環境中
需要在 `logging.basicConfig()` 中設定 `force=True` 來強制覆蓋
- ### Question

    logging.basicConfig(
        level=logging.DEBUG,
        format="%(asctime)s %(levelname)s %(name)s: %(message)s",
    )
    print('__name__:', __name__)
    logger = logging.getLogger(__name__)
    logger.debug('test')

執行結果：

    DEBUG:__main__:test
    __name__: __main__

為何沒有遵循 format？
- ### gpt-5.2 (2026/01/29)
你這個現象其實分兩件事：

### 1) 為什麼沒有套用你的 `format`？

因為 **`logging.basicConfig()` 沒有真的生效**。
`basicConfig()` 的規則是：**root logger 已經有 handler 的話，它就什麼都不做**（所以你看到的是預設格式 `%(levelname)s:%(name)s:%(message)s` → `DEBUG:__main__:test`）。

這常見在：

* 你在 REPL / Jupyter / 某些框架（uvicorn/pytest 等）跑，logging 早就先被設定過
* 你的程式在別的地方先 import 了某個會設定 logging 的套件

✅ 解法（Python 3.8+）：加 `force=True` 強制覆蓋

    import logging
    import sys

    logging.basicConfig(
        level=logging.DEBUG,
        format="%(asctime)s %(levelname)s %(name)s: %(message)s",
        datefmt="%Y-%m-%d %H:%M:%S",
        handlers=[logging.StreamHandler(sys.stdout)],
        force=True,
    )

    print('__name__:', __name__, flush=True)
    logger = logging.getLogger(__name__)
    logger.debug('test')

如果你 Python < 3.8 沒有 `force`，就用「清掉舊 handler」：

    import logging

    for h in logging.root.handlers[:]:
        logging.root.removeHandler(h)

    logging.basicConfig(
        level=logging.DEBUG,
        format="%(asctime)s %(levelname)s %(name)s: %(message)s",
    )

---

### 2) 為什麼 log 行跑在 `print` 前面？

因為 **logging 預設輸出到 stderr**，`print` 是 stdout；兩個 stream 的刷新順序可能不同，所以看起來 log 先出現。

上面我把 handler 指到 `sys.stdout`，再加 `print(..., flush=True)`，順序就會一致。

---

如果你告訴我你是在哪個環境跑（純 python / uvicorn / pytest / Jupyter），我可以給你該環境「最乾淨」的設定方式。

<br>

{%hackmd vaaMgNRPS4KGJDSFG0ZE0w %}