python / python/cpython

`logging.log` doesn't naively work as audit hook for `sys.addaudithook`

未關閉
#98,105 1 則留言 0 個 reaction 已指派 0 人 在 GitHub 檢視

還沒有人認領這個 Issue。

stdlib type-bug
主要語言
Python
星號
77.2k
分支
36k
平均合併
1 天 9 小時
30 天內合併 PR
558

描述

Bug report

Documentation for sys.addaudithook states "Hooks can then log the event [...]".
This works when I don't log, but instead print:

sys.addaudithook(print)
id(0)  # printed

However, nothing gets logged when I follow the suggestion to log, like:

sys.addaudithook(functools.partial(logging.warning, 'Audit hook %s %s'))
id(0)  # NOT logged

The cause is that logging.Logger._log (called by logging.warning) tries to find the caller (to populate module, lineno, funcName log format fields). For this, logging.Logger._log itself then causes audit events, which again call the audit hook. That results in infinite recursion, i.e. a RecursionError exception, which aborts the audit hook, and silences logging.

Workaround

By (temporarily) modifying logging._srcfile, the attempt to find the caller is skipped (and the log format fields are instead populated as "unknown"), infinite recursion and exception are prevented, and logging does happen:

sys.addaudithook(functools.partial(logging.warning, 'Audit hook %s %s'))
logging._srcfile = None  # prevent finding caller
id(0)  # logged

This is existing functionality, only (?) documented in source (file logging.__init__, line 188: "Setting _srcfile to None will prevent findCaller() from being called. This way, you can avoid the overhead of fetching caller information"). Though it works, the workaround is hard to find and not ideal.

Solutions

  • Ideally, logging should not attempt to gather caller info in an audit hook (however, this requires tight coupling of the logging and sys modules, so they understand each others' internals)
  • Equally user-friendly, audit events would not be generated within audit hooks (that risks incompleteness of auditing, but so does silencing logging)
  • Less user-friendly, a keyword parameter (e.g. find_caller: bool = True) could be added to the signature of each log function, logging.Logger._log can inspect it, and the documentation for sys.addaudithook should recommend to use find_caller=False for logging in audit hooks
# logging.Logger._log
if logging._srcfile and find_caller:
    ...

# to use
sys.addaudithook(functools.partial(logging.warning, 'Audit hook %s %s', find_caller=False))
id(0)  # logged
  • At the minimum, the documentation for sys.addaudithook should recommend above workaround, i.e. temporarily set logging._srcfile = None
def my_log(event, args):
    save_srcfile = logging._srcfile
    logging._srcfile = None
    logging.warning('Audit hook %s %s', event, args)
    logging._srcfile = save_srcfile

sys.addaudithook(my_log)
id(0)  # logged

Environment

The above issue exists in all Python versions supporting sys.addaudithook, i.e. 3.8, 3.9, 3.10, and 3.11.
I tested on 3.8.10, 3.9.13, 3.10.4, and 3.110rc2 on Windows 11 64 bit.

貢獻指南

開啟貢獻指南

從這裡開始

  1. 先讀完整個 Issue,再讀專案的貢獻指南。
  2. 在 Issue 下留言說明你要接手 —— 這能避免兩個人做同樣的事。
  3. Fork 儲存庫,在一個分支上完成修改。
  4. 送出 Pull Request,並在描述裡引用這個 Issue 編號。

研究方向

使用 sys.addaudithook 和 logging.warning 範例重現遞迴,然後閱讀 logging.init,尤其是 Logger._log、findCaller() 和 _srcfile 註解,同時參閱 sys.addaudithook 文件。確定提出的行為或文件變更中哪些是可接受的,並驗證 audit hook 記錄不再遞迴或靜默失敗。

由索引模型根據 Issue 內容生成。

評估

技術堆疊
python
領域
documentation, security
Issue 類型
缺陷
難度
5/5
預估耗時
一週以上
活躍度
停滯
描述清晰度
基本清楚
新手友好度
25/100

把新 issue 寄到你的電子郵件信箱

精選適合新手參與的 GitHub issue 摘要。