`logging.log` doesn't naively work as audit hook for `sys.addaudithook`
Nessuno ha ancora preso questa issue.
- Lingua principale
- Python
- Stelle
- 77.2k
- Fork
- 36k
- Merge medio
- 1g 9h
- PR unite (30g)
- 558
Descrizione
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,
loggingshould not attempt to gather caller info in an audit hook (however, this requires tight coupling of theloggingandsysmodules, 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._logcan inspect it, and the documentation forsys.addaudithookshould recommend to usefind_caller=Falsefor 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.addaudithookshould recommend above workaround, i.e. temporarily setlogging._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.
Guida per i contributori
Apri la guida per i contributori
Come iniziare
- Leggi tutta la issue e poi la guida ai contributi del progetto.
- Commenta sulla issue per dire che te ne occupi tu — evita che due persone facciano lo stesso lavoro.
- Fai un fork del repository e lavora su un branch.
- Apri una pull request che faccia riferimento al numero della issue.
Direzione di ricerca
Riproduci la ricorsione usando gli esempi sys.addaudithook e logging.warning, quindi leggi logging.init, in particolare Logger._log, findCaller() e la nota su _srcfile, insieme alla documentazione di sys.addaudithook. Determina quale comportamento proposto o quale modifica alla documentazione sia accettabile e verifica che il logging tramite audit hook non ricorra più né fallisca silenziosamente.
Scritto dal modello di indicizzazione a partire dal testo della issue.
Valutazione
- Stack tecnologico
- python
- Ambito
- documentation, security
- Tipo di issue
- Bug
- Difficoltà
- 5/5
- Tempo stimato
- Più di una settimana
- Stato di attività
- Ferma
- Chiarezza
- Abbastanza chiara
- Idoneità per principianti
- 25/100