Add sys.unraisablehook() to customize how "unraisable exceptions" are logged

[graingert]

BPO	36829
Nosy	@vstinner, @serhiy-storchaka, @graingert, @matrixise, @ZackerySpytz, @tirkarthi
PRs	bpo-36829: Add a -X option to abort in PyErr_WriteUnraisable() #13175 bpo-36829: Add sys.unraisablehook() #13187 [3.7] bpo-36829: Enhance PyErr_WriteUnraisable() #13487 bpo-36829: Add _PyErr_WriteUnraisableMsg() #13488 bpo-36829: Add test.support.catch_unraisable_exception() #13490 bpo-36829: PyErr_WriteUnraisable() normalizes exception #13507 bpo-36829: Document test.support.catch_unraisable_exception() #13554 bpo-36829: sys.excepthook and sys.unraisablehook flush #13620 bpo-36829: test_threading: Fix a ref cycle #13752
Files	gc_callback.py uncollectable.py io_destructor.py site_hook.patch too_late_unraisable.py hook_file.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2019-05-27.22:57:04.603>
created_at = <Date 2019-05-07.12:10:07.913>
labels = ['interpreter-core', 'type-feature', '3.8']
title = 'Add sys.unraisablehook() to customize how "unraisable exceptions" are logged'
updated_at = <Date 2019-07-09.10:38:23.720>
user = 'https://github.com/graingert'

bugs.python.org fields:

activity = <Date 2019-07-09.10:38:23.720>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2019-05-27.22:57:04.603>
closer = 'vstinner'
components = ['Interpreter Core']
creation = <Date 2019-05-07.12:10:07.913>
creator = 'graingert'
dependencies = []
files = ['48313', '48314', '48315', '48316', '48321', '48329']
hgrepos = []
issue_num = 36829
keywords = ['patch']
message_count = 32.0
messages = ['341708', '341718', '341736', '341752', '341787', '341868', '342000', '342001', '342003', '342011', '342013', '342014', '342413', '342482', '342618', '343161', '343170', '343201', '343213', '343245', '343247', '343250', '343253', '343255', '343286', '343412', '343436', '343609', '343697', '343778', '344318', '347544']
nosy_count = 6.0
nosy_names = ['vstinner', 'serhiy.storchaka', 'graingert', 'matrixise', 'ZackerySpytz', 'xtreak']
pr_nums = ['13175', '13187', '13487', '13488', '13490', '13507', '13554', '13620', '13752']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue36829'
versions = ['Python 3.8']

[graingert]

Currently it's quite easy for these errors to go unnoticed.

I'd like a way to easily detect these in CI.

nedbat suggested piping the process output to another tool, and looking for 'Exception ignored in:' but this seems a little diff

[matrixise]

Hi Serhiy,

What do you think about this idea?

Normally, we could use -W error when there is an exception.

[serhiy-storchaka]

It looks like a good idea to me. But it should not be -W error. It should be an -X option, and this option should be used exclusively for debugging user extension modules.

[graingert]

this option should be used exclusively for debugging user extension modules.

I have a very large codebase that fires the odd ResourceWarning, and after fixing them all I'd like to ensure that they do not reoccur. When using -W error it still won't fail CI. So I would use this -X option for more than debugging user extension modules

[ZackerySpytz]

I am working on this issue.

[vstinner]

I wrote PR 13187 to control how unraisable exceptions are handled.

Attached uncollectable.py, gc_callback.py and io_destructor.py examples can be
used to test unraisable exceptions.

Without my PR:
---

$ ./python -Werror uncollectable.py
ResourceWarning: gc: 2 uncollectable objects at shutdown; use gc.set_debug(gc.DEBUG_UNCOLLECTABLE) to list them

$ ./python gc_callback.py
Exception ignored in: <function wr_callback at 0x7f9b48d2b2b0>
Traceback (most recent call last):
  File "gc_callback.py", line 7, in wr_callback
    raise ValueError(42)
ValueError: 42

$ ./python -X dev io_destructor.py
io_destructor.py:4: ResourceWarning: unclosed file <_io.TextIOWrapper name='io_destructor.py' mode='r' encoding='UTF-8'>
  f = None
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Exception ignored in: <_io.TextIOWrapper name='io_destructor.py' mode='r' encoding='UTF-8'>
OSError: [Errno 9] Bad file descriptor

---

For example, apply attached site_hook.patch to install a custom unraisablehook.

Output with my PR + site_hook.patch:
---

$ ./python -Werror uncollectable.py
ResourceWarning: gc: 2 uncollectable objects at shutdown; use gc.set_debug(gc.DEBUG_UNCOLLECTABLE) to list them

$ ./python gc_callback.py
Exception ignored in: <function wr_callback at 0x7fb59a0f9510>
  File "gc_callback.py", line 7, in wr_callback
    raise ValueError(42)
ValueError: 42
Traceback (most recent call last):
  File "gc_callback.py", line 11, in <module>
    obj = None

$ ./python -X dev io_destructor.py
io_destructor.py:4: ResourceWarning: unclosed file <_io.TextIOWrapper name='io_destructor.py' mode='r' encoding='UTF-8'>
  f = None
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Exception ignored in: <_io.TextIOWrapper name='io_destructor.py' mode='r' encoding='UTF-8'>
OSError: [Errno 9] Bad file descriptor
Traceback (most recent call last):
  File "io_destructor.py", line 4, in <module>
    f = None

---

The first good news is that it *is* possible to write a custom hook for unraisable for one of the last unraisable exception: _PyGC_DumpShutdownStats() which logs "uncollectable objects at shutdown".

When an unraisable exceptions is logged before Python finalization, the hook can inspect the Python stack to see where the exception has been raised which helps debugging.

[vstinner]

too_late_unraisable.py is an example where PyErr_WriteUnraisable() is called very lated during Python finalization to be handled by user code. A destructor (del) fails on print() because the stream has been closed.

PyErr_WriteUnraisable() is called by _PyGC_CollectNoFail() at the *end* of PyImport_Cleanup(). At this point, the sys module has already been cleared, as all other modules. A custom sys.unraisablehook cannot be used, because sys has been called.

[vstinner]

Ok, let me come back to the initial issue:

Thomas Grainger:

Currently it's quite easy for these errors to go unnoticed. I'd like a way to easily detect these in CI. nedbat suggested piping the process output to another tool, and looking for 'Exception ignored in:' but this seems a little diff

When PyErr_WriteUnraisable() is called before Python finalization, my PR 13187 allows to handle these exceptions: log them in a dedicated file, abort the process, maybe even open a network connection, etc. The hook allows to implement your chosen behavior.

The problem is more during Python finalization: see attached too_late_unraisable.py example and my previous comment. If PyErr_WriteUnraisable() is called after sys.stderr is closed or closed to None, the function does nothing: the exception is not logged.

The question now becomes: do *all* calls to PyErr_WriteUnraisable() must abort the process? What is the point? Only a very low level debugger like gdb can be used to see the exception.

@thomas Grainger: Do you want to have to use gdb to trace such very level exception?

IMHO sadly when PyErr_WriteUnraisable() is called way too late, we should simply ignore such exceptions. And so my PR 13187 is good enough to cover most cases.

If someone cares about exceptions raised very late during Python finalization, Python finalization should be enhanced. But this code is very fragile and is not deterministic. It is a work in progress for years to enhance it.

[graingert]

The point for me is that CI will fail if it happens, then I can use gdb to
find out the cause

On Thu, 9 May 2019, 23:17 STINNER Victor, <report@bugs.python.org> wrote:

STINNER Victor <vstinner@redhat.com> added the comment:

Ok, let me come back to the initial issue:

Thomas Grainger:
> Currently it's quite easy for these errors to go unnoticed. I'd like a
way to easily detect these in CI. nedbat suggested piping the process
output to another tool, and looking for 'Exception ignored in:' but this
seems a little diff

When PyErr_WriteUnraisable() is called before Python finalization, my PR
13187 allows to handle these exceptions: log them in a dedicated file,
abort the process, maybe even open a network connection, etc. The hook
allows to implement your chosen behavior.

The problem is more during Python finalization: see attached
too_late_unraisable.py example and my previous comment. If
PyErr_WriteUnraisable() is called after sys.stderr is closed or closed to
None, the function does nothing: the exception is not logged.

The question now becomes: do *all* calls to PyErr_WriteUnraisable() must
abort the process? What is the point? Only a very low level debugger like
gdb can be used to see the exception.

@thomas Grainger: Do you want to have to use gdb to trace such very level
exception?

IMHO sadly when PyErr_WriteUnraisable() is called way too late, we should
simply ignore such exceptions. And so my PR 13187 is good enough to cover
most cases.

If someone cares about exceptions raised very late during Python
finalization, Python finalization should be enhanced. But this code is very
fragile and is not deterministic. It is a work in progress for years to
enhance it.

----------

---

Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue36829\>

---

[vstinner]

The point for me is that CI will fail if it happens, then I can use gdb to find out the cause

I'm not comfortable with forcing users to use a low-level debugger to debug "unraisable exceptions".

I tried PR 13175 on the test suite by forcing the option to 1: always call Py_FatalError(). Many tests break:

14 tests failed:
test_asyncio test_cmd_line test_coroutines test_cprofile
test_exceptions test_generators test_import test_io
test_raise test_repl test_signal test_ssl test_urllib
test_yield_from

Examples:

test_error_through_destructor (test.test_io.CBufferedReaderTest) ... Fatal Python error: Unraisable exception

FAIL: test_warn_on_full_buffer (test.test_signal.WakeupSocketSignalTests)
FAIL: test_send_error (test.test_signal.WakeupSocketSignalTests)
FAIL: test_wakeup_write_error (test.test_signal.WakeupSignalTests)

test_unraisable (test.test_exceptions.ExceptionTests) ... Fatal Python error: Unraisable exception

test_generators:

Trying:
del g
Expecting nothing
Fatal Python error: Unraisable exception

etc.

Unraisable exceptions are bad, but it's really hard to fix all of them. They are too many cases where Python is unable to pass exceptions to the parent.

If you want to make the situation better, maybe we should investigate where Python cannot raise exceptions and try to make it possible.

IMHO my PR 13187 adding sys.unraisablehook() is more usable/reasonable option.

--

Thomas Grainger: which code are you running on your CI? Did you try PR 13175 on your CI? Try it with this additional change, to always crash on PyErr_WriteUnraisable(). Does your CI still pass?

diff --git a/Include/cpython/coreconfig.h b/Include/cpython/coreconfig.h
index 375c0b641d..a775584553 100644
--- a/Include/cpython/coreconfig.h
+++ b/Include/cpython/coreconfig.h
@@ -426,7 +426,8 @@ typedef struct {
         .buffered_stdio = -1, \
         ._install_importlib = 1, \
         .check_hash_pycs_mode = NULL, \
-        ._frozen = -1}
+        ._frozen = -1, \
+        .abort_unraisable = 1}
 /* Note: _PyCoreConfig_INIT sets other fields to 0/NULL */
 
 #ifdef __cplusplus

[graingert]

I'm not comfortable with forcing users to use a low-level debugger to
debug "unraisable exceptions".

Defaulting to noop when the hook fails means I'll never notice the failure
to be able to debug it

On Fri, 10 May 2019, 00:42 STINNER Victor, <report@bugs.python.org> wrote:

STINNER Victor <vstinner@redhat.com> added the comment:

> The point for me is that CI will fail if it happens, then I can use gdb
to find out the cause

I'm not comfortable with forcing users to use a low-level debugger to
debug "unraisable exceptions".

I tried PR 13175 on the test suite by forcing the option to 1: always call
Py_FatalError(). Many tests break:

14 tests failed:
test_asyncio test_cmd_line test_coroutines test_cprofile
test_exceptions test_generators test_import test_io
test_raise test_repl test_signal test_ssl test_urllib
test_yield_from

Examples:

test_error_through_destructor (test.test_io.CBufferedReaderTest) ... Fatal
Python error: Unraisable exception

FAIL: test_warn_on_full_buffer (test.test_signal.WakeupSocketSignalTests)
FAIL: test_send_error (test.test_signal.WakeupSocketSignalTests)
FAIL: test_wakeup_write_error (test.test_signal.WakeupSignalTests)

test_unraisable (test.test_exceptions.ExceptionTests) ... Fatal Python
error: Unraisable exception

test_generators:

Trying:
del g
Expecting nothing
Fatal Python error: Unraisable exception

etc.

Unraisable exceptions are bad, but it's really hard to fix all of them.
They are too many cases where Python is unable to pass exceptions to the
parent.

If you want to make the situation better, maybe we should investigate
where Python cannot raise exceptions and try to make it possible.

IMHO my PR 13187 adding sys.unraisablehook() is more usable/reasonable
option.

--

Thomas Grainger: which code are you running on your CI? Did you try PR
13175 on your CI? Try it with this additional change, to always crash on
PyErr_WriteUnraisable(). Does your CI still pass?

diff --git a/Include/cpython/coreconfig.h b/Include/cpython/coreconfig.h
index 375c0b641d..a775584553 100644
--- a/Include/cpython/coreconfig.h
+++ b/Include/cpython/coreconfig.h
@@ -426,7 +426,8 @@ typedef struct {
.buffered_stdio = -1, \
._install_importlib = 1, \
.check_hash_pycs_mode = NULL, \

•    .\_frozen = -1}
  

•    .\_frozen = -1, \\
  

•    .abort_unraisable = 1}
  

/* Note: _PyCoreConfig_INIT sets other fields to 0/NULL */

#ifdef __cplusplus

----------

---

Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue36829\>

---