Merge pull request #314 from steve-s/add/improve-debug-ctx-usability

Improve debug context usability

Makefile

@@ -10,7 +10,7 @@ dist-info:
 	python3 setup.py dist_info
 
 debug:
-	HPY_DEBUG=1 make all
+	HPY_DEBUG_BUILD=1 make all
 
 autogen:
 	python3 -m hpy.tools.autogen .
@@ -53,7 +53,7 @@ valgrind:
 	PYTHONMALLOC=malloc valgrind --suppressions=hpy/tools/valgrind/python.supp --suppressions=hpy/tools/valgrind/hpy.supp --leak-check=full --show-leak-kinds=definite,indirect --log-file=/tmp/valgrind-output python -m pytest --valgrind --valgrind-log=/tmp/valgrind-output test/
 
 docs-examples-tests:
-	python docs/examples/simple-example/setup.py install
+	python docs/examples/simple-example/setup.py --hpy-abi=universal install
 	python docs/examples/mixed-example/setup.py install
-	python docs/examples/snippets/setup.py install
+	python docs/examples/snippets/setup.py --hpy-abi=universal install
 	pytest docs/examples/tests.py

c_test/Makefile

@@ -2,12 +2,16 @@ CC ?= gcc
 INCLUDE=-I.. -I../hpy/devel/include -I../hpy/debug/src/include
 CFLAGS = -O0 -UNDEBUG -g -Wall -Werror -Wfatal-errors $(INCLUDE) -DHPY_UNIVERSAL_ABI
 
-test: test_debug_handles
+test: test_debug_handles test_stacktrace
 	./test_debug_handles
+	./test_stacktrace
 
 test_debug_handles: test_debug_handles.o ../hpy/debug/src/dhqueue.o
 	$(CC) -o $@ $^
 
+test_stacktrace: test_stacktrace.o ../hpy/debug/src/stacktrace.o
+	$(CC) -o $@ $^
+
 %.o : %.c
 	$(CC) -c $(CFLAGS) $< -o $@
 

c_test/test_stacktrace.c

@@ -0,0 +1,22 @@
+// Smoke test for the create_stacktrace function
+
+#include <stdarg.h>
+#include "acutest.h" // https://github.com/mity/acutest
+#include "hpy/debug/src/debug_internal.h"
+
+void test_create_stacktrace(void)
+{
+    char *trace;
+    create_stacktrace(&trace, 16);
+    if (trace != NULL) {
+        printf("\n\nTRACE:\n%s\n\n", trace);
+        free(trace);
+    }
+}
+
+#define MYTEST(X) { #X, X }
+
+TEST_LIST = {
+        MYTEST(test_create_stacktrace),
+        { NULL, NULL }
+};

docs/debug-mode.rst

@@ -28,6 +28,129 @@ The debugging context can already check for:
 * Writing to a memory which should be read-only, for example,
   the buffer returned by ``HPyUnicode_AsUTF8AndSize``.
 
-An HPy module may be explicitly loaded in debug mode using::
+
+Activating Debug Mode
+---------------------
+
+The debug mode works only for extensions built with HPy universal ABI.
+
+To enable the debug mode, use environment variable ``HPY_DEBUG``.
+If ``HPY_DEBUG=1``, then all HPy modules are loaded with debug context.
+Alternatively ``HPY_DEBUG`` can be set to a comma separated list of names
+of the modules that should be loaded in the debug mode.
+
+In order to verify that your extension is being loaded in the HPy debug mode,
+use environment variable ``HPY_LOG``. If this variable is set, then all HPy
+extensions built in universal ABI mode print a message, such as:
+
+.. code-block:: console
+
+    > import snippets
+    Loading 'snippets' in HPy universal mode with a debug context
+
+.. Note: the output above is tested in test_leak_detector_with_traces_output
+
+If the extension is built in CPython ABI mode, then the ``HPY_LOG``
+environment variable has no effect.
+
+An HPy extension module may be also explicitly loaded in debug mode using::
 
   mod = hpy.universal.load(module_name, so_filename, debug=True)
+
+When loading HPy extensions explicitly, environment variables ``HPY_LOG``
+and ``HPY_DEBUG`` have no effect for that extension.
+
+
+Using Debug Mode
+----------------
+
+The HPy debug module exposes ``LeakDetector`` class for detection of
+leaked handles. ``LeakDetector`` can be used to check that some code does
+not leave behind unclosed ``HPy`` handles. For example:
+
+.. literalinclude:: examples/tests.py
+  :language: python
+  :start-at: def test_leak_detector
+  :end-before: # END: test_leak_detector
+
+Additionally, the debug module also exposes pytest fixture ``hpy_debug`` that
+, for the time being, enables the ``LeakDetector``, but may also enable other
+useful debugging facilities.
+
+.. literalinclude:: examples/tests.py
+  :language: python
+  :start-at: from hpy.debug.pytest import hpy_debug
+  :end-at: # Run some HPy extension code
+
+**ATTENTION**: the usage of ``LeakDetector`` or ``hpy_debug`` by itself does not
+enable the HPy debug mode! If the debug mode is not enabled for any extension,
+then those features do nothing useful (but also nothing harmful).
+
+When dealing with handle leaks, it is useful to get a stack trace of the
+allocation of the leaked handle. This feature has large memory requirements
+and is therefore opt-in. It can be activated by:
+
+.. literalinclude:: examples/tests.py
+  :language: python
+  :start-at: hpy.debug.set_handle_stack_trace_limit
+  :end-at: hpy.debug.set_handle_stack_trace_limit
+
+and disabled by:
+
+.. literalinclude:: examples/tests.py
+  :language: python
+  :start-at: hpy.debug.disable_handle_stack_traces
+  :end-at: hpy.debug.disable_handle_stack_traces
+
+.. Note: the following output is tested in test_leak_detector_with_traces_output
+
+Example
+-------
+
+Following HPy function leaks a handle:
+
+.. literalinclude:: examples/snippets/snippets.c
+  :start-after: // BEGIN: test_leak_stacktrace
+  :end-before: // END: test_leak_stacktrace
+
+When this script is executed in debug mode:
+
+.. literalinclude:: examples/debug-example.py
+  :language: python
+  :end-before: print("SUCCESS")
+
+The output is::
+
+    Traceback (most recent call last):
+      File "/path/to/hpy/docs/examples/debug-example.py", line 7, in <module>
+        snippets.test_leak_stacktrace()
+      File "/path/to/hpy/debug/leakdetector.py", line 43, in __exit__
+        self.stop()
+      File "/path/to/hpy/debug/leakdetector.py", line 36, in stop
+        raise HPyLeakError(leaks)
+    hpy.debug.leakdetector.HPyLeakError: 1 unclosed handle:
+        <DebugHandle 0x556bbcf907c0 for 42>
+    Allocation stacktrace:
+    /path/to/site-packages/hpy-0.0.4.dev227+gd7eeec6.d20220510-py3.8-linux-x86_64.egg/hpy/universal.cpython-38d-x86_64-linux-gnu.so(debug_ctx_Long_FromLong+0x45) [0x7f1d928c48c4]
+    /path/to/site-packages/hpy_snippets-0.0.0-py3.8-linux-x86_64.egg/snippets.hpy.so(+0x122c) [0x7f1d921a622c]
+    /path/to/site-packages/hpy_snippets-0.0.0-py3.8-linux-x86_64.egg/snippets.hpy.so(+0x14b1) [0x7f1d921a64b1]
+    /path/to/site-packages/hpy-0.0.4.dev227+gd7eeec6.d20220510-py3.8-linux-x86_64.egg/hpy/universal.cpython-38d-x86_64-linux-gnu.so(debug_ctx_CallRealFunctionFromTrampoline+0xca) [0x7f1d928bde1e]
+    /path/to/site-packages/hpy_snippets-0.0.0-py3.8-linux-x86_64.egg/snippets.hpy.so(+0x129b) [0x7f1d921a629b]
+    /path/to/site-packages/hpy_snippets-0.0.0-py3.8-linux-x86_64.egg/snippets.hpy.so(+0x1472) [0x7f1d921a6472]
+    /path/to/libpython3.8d.so.1.0(+0x10a022) [0x7f1d93807022]
+    /path/to/libpython3.8d.so.1.0(+0x1e986b) [0x7f1d938e686b]
+    /path/to/libpython3.8d.so.1.0(+0x2015e9) [0x7f1d938fe5e9]
+    /path/to/libpython3.8d.so.1.0(_PyEval_EvalFrameDefault+0x1008c) [0x7f1d938f875a]
+    /path/to/libpython3.8d.so.1.0(PyEval_EvalFrameEx+0x64) [0x7f1d938e86b8]
+    /path/to/libpython3.8d.so.1.0(_PyEval_EvalCodeWithName+0xfaa) [0x7f1d938fc8af]
+    /path/to/libpython3.8d.so.1.0(PyEval_EvalCodeEx+0x86) [0x7f1d938fca25]
+    /path/to/libpython3.8d.so.1.0(PyEval_EvalCode+0x4b) [0x7f1d938e862b]
+
+For the time being, HPy uses the glibc ``backtrace`` and ``backtrace_symbols``
+`functions <https://www.gnu.org/software/libc/manual/html_node/Backtraces.html>`_.
+Therefore all their caveats and limitations apply. Usual recommendations to get
+more symbols in the traces and not only addresses, such as ``snippets.hpy.so(+0x122c)``, are:
+
+* link your native code with ``-rdynamic`` flag (``LDFLAGS="-rdynamic"``)
+* build your code without optimizations and with debug symbols (``CFLAGS="-O0 -g"``)
+* use ``addr2line`` command line utility, e.g.: ``addr2line -e /path/to/snippets.hpy.so -C -f +0x122c``

docs/examples/debug-example.py

@@ -0,0 +1,10 @@
+# Run with HPY_DEBUG=1
+import hpy.debug
+import snippets
+
+hpy.debug.set_handle_stack_trace_limit(16)
+from hpy.debug.pytest import LeakDetector
+with LeakDetector() as ld:
+    snippets.test_leak_stacktrace()
+
+print("SUCCESS")  # Should not be actually printed

docs/examples/snippets/snippets.c

@@ -38,11 +38,26 @@ static HPy test_foo_and_is_same_object_impl(HPyContext *ctx, HPy self,
     return HPyLong_FromLong(ctx, is_same_object(ctx, args[0], args[1]));
 }
 
+// BEGIN: test_leak_stacktrace
+HPyDef_METH(test_leak_stacktrace, "test_leak_stacktrace",
+            test_leak_stacktrace_impl, HPyFunc_NOARGS)
+static HPy test_leak_stacktrace_impl(HPyContext *ctx, HPy self)
+{
+    HPy num = HPyLong_FromLong(ctx, 42);
+    if (HPy_IsNull(num)) {
+        return HPy_NULL;
+    }
+    // No HPy_Close(ctx, num);
+    return HPy_Dup(ctx, ctx->h_None);
+}
+// END: test_leak_stacktrace
+
 // ------------------------------------
 // Dummy module definition, so that we can test the snippets
 
 static HPyDef *Methods[] = {
         &test_foo_and_is_same_object,
+        &test_leak_stacktrace,
         NULL,
 };
 

docs/examples/tests.py

@@ -1,3 +1,9 @@
+import os
+import os.path
+import re
+import subprocess
+import sys
+
 import simple
 import mixed
 import hpyvarargs
@@ -22,3 +28,45 @@ def test_snippets():
     x = 2
     assert snippets.test_foo_and_is_same_object(x, x) == 1
     assert snippets.test_foo_and_is_same_object(x, 42) == 0
+
+
+def test_leak_detector():
+    from hpy.debug.pytest import LeakDetector
+    with LeakDetector() as ld:
+        # add_ints is an HPy C function. If it forgets to close a handle,
+        # LeakDetector will complain
+        assert mixed.add_ints(40, 2) == 42
+# END: test_leak_detector
+
+from hpy.debug.pytest import hpy_debug
+def test_that_uses_leak_detector_fixture(hpy_debug):
+    # Run some HPy extension code
+    assert mixed.add_ints(40, 2) == 42
+
+
+def test_leak_detector_with_traces():
+    import hpy.debug
+    hpy.debug.set_handle_stack_trace_limit(16)
+    assert mixed.add_ints(40, 2) == 42
+    hpy.debug.disable_handle_stack_traces()
+
+
+def test_leak_detector_with_traces_output():
+    # Update the debug documentation if anything here changes!
+    env = os.environ.copy()
+    env['HPY_DEBUG'] = '1'
+    env['HPY_LOG'] = '1'
+    script = os.path.join(os.path.dirname(__file__), 'debug-example.py')
+    result = subprocess.run([sys.executable, script], env=env,
+                            stdout=subprocess.PIPE, stderr=subprocess.PIPE)
+    # Rudimentary check that the output contains what we have in the documentation
+    out = result.stdout.decode('latin-1')
+    assert out == "Loading 'snippets' in HPy universal mode with a debug context" + os.linesep
+    err = result.stderr.decode('latin-1')
+    assert 'hpy.debug.leakdetector.HPyLeakError: 1 unclosed handle:' in err
+    assert re.search('<DebugHandle 0x[\\da-h]* for 42>', err)
+    assert 'Allocation stacktrace:' in err
+    if sys.platform.startswith("linux"):
+        assert 'snippets.hpy.so' in err  # Should be somewhere in the stack trace
+    else:
+        assert 'At the moment this is only supported on Linux with glibc' in err

hpy/debug/__init__.py

@@ -1 +1,11 @@
 from .leakdetector import HPyDebugError, HPyLeakError, LeakDetector
+
+
+def set_handle_stack_trace_limit(limit):
+    from hpy.universal import _debug
+    _debug.set_handle_stack_trace_limit(limit)
+
+
+def disable_handle_stack_traces():
+    from hpy.universal import _debug
+    _debug.set_handle_stack_trace_limit(None)

hpy/debug/src/_debugmod.c

@@ -161,6 +161,27 @@ static UHPy set_on_invalid_handle_impl(HPyContext *uctx, UHPy u_self, UHPy u_arg
     return HPy_Dup(uctx, uctx->h_None);
 }
 
+HPyDef_METH(set_handle_stack_trace_limit, "set_handle_stack_trace_limit",
+            set_handle_stack_trace_limit_impl, HPyFunc_O, .doc=
+                    "Set the limit to captured HPy handles allocations stack traces. "
+                    "None means do not capture the stack traces.")
+static UHPy set_handle_stack_trace_limit_impl(HPyContext *uctx, UHPy u_self, UHPy u_arg)
+{
+    HPyContext *dctx = hpy_debug_get_ctx(uctx);
+    HPyDebugInfo *info = get_info(dctx);
+    if (HPy_Is(uctx, u_arg, uctx->h_None)) {
+        info->handle_alloc_stacktrace_limit = 0;
+    } else {
+        assert(!HPyErr_Occurred(uctx));
+        HPy_ssize_t newlimit = HPyLong_AsSsize_t(uctx, u_arg);
+        if (newlimit == -1 && HPyErr_Occurred(uctx)) {
+            return HPy_NULL;
+        }
+        info->handle_alloc_stacktrace_limit = newlimit;
+    }
+    return HPy_Dup(uctx, uctx->h_None);
+}
+
 
 /* ~~~~~~ DebugHandleType and DebugHandleObject ~~~~~~~~
 
@@ -253,12 +274,14 @@ static UHPy DebugHandle_repr_impl(HPyContext *uctx, UHPy self)
     UHPy uh_id = HPy_NULL;
     UHPy uh_args = HPy_NULL;
     UHPy uh_result = HPy_NULL;
+    UHPy h_trace_header = HPy_NULL;
+    UHPy h_trace = HPy_NULL;
 
     const char *fmt = NULL;
     if (dh->handle->is_closed)
-        fmt = "<DebugHandle 0x%x CLOSED>";
+        fmt = "<DebugHandle 0x%x CLOSED>\n%s%s";
     else
-        fmt = "<DebugHandle 0x%x for %r>";
+        fmt = "<DebugHandle 0x%x for %r>\n%s%s";
 
     // XXX: switch to HPyUnicode_FromFormat when we have it
     uh_fmt = HPyUnicode_FromString(uctx, fmt);
@@ -269,10 +292,24 @@ static UHPy DebugHandle_repr_impl(HPyContext *uctx, UHPy self)
     if (HPy_IsNull(uh_id))
         goto exit;
 
+    const char *trace_header;
+    const char *trace;
+    if (dh->handle->allocation_stacktrace) {
+        trace_header = "Allocation stacktrace:\n";
+        trace = dh->handle->allocation_stacktrace;
+    } else {
+        trace_header = "To get the stack trace of where it was allocated use:\nhpy.debug.";
+        trace = set_handle_stack_trace_limit.meth.name;
+    }
+    h_trace_header = HPyUnicode_FromString(uctx, trace_header);
+    h_trace = HPyUnicode_FromString(uctx, trace);
+
     if (dh->handle->is_closed)
-        uh_args = HPyTuple_FromArray(uctx, (UHPy[]){uh_id}, 1);
+        uh_args = HPyTuple_FromArray(uctx, (UHPy[]){uh_id,
+                                                    h_trace_header, h_trace}, 3);
     else
-        uh_args = HPyTuple_FromArray(uctx, (UHPy[]){uh_id, dh->handle->uh}, 2);
+        uh_args = HPyTuple_FromArray(uctx, (UHPy[]){uh_id, dh->handle->uh,
+                                                    h_trace_header, h_trace}, 4);
     if (HPy_IsNull(uh_args))
         goto exit;
 
@@ -282,6 +319,8 @@ static UHPy DebugHandle_repr_impl(HPyContext *uctx, UHPy self)
     HPy_Close(uctx, uh_fmt);
     HPy_Close(uctx, uh_id);
     HPy_Close(uctx, uh_args);
+    HPy_Close(uctx, h_trace);
+    HPy_Close(uctx, h_trace_header);
     return uh_result;
 }
 
@@ -336,6 +375,7 @@ static HPyDef *module_defines[] = {
     &get_protected_raw_data_max_size,
     &set_protected_raw_data_max_size,
     &set_on_invalid_handle,
+    &set_handle_stack_trace_limit,
     NULL
 };
 

hpy/debug/src/debug_ctx.c

@@ -37,6 +37,7 @@ int hpy_debug_ctx_init(HPyContext *dctx, HPyContext *uctx)
     info->uh_on_invalid_handle = HPy_NULL;
     info->closed_handles_queue_max_size = DEFAULT_CLOSED_HANDLES_QUEUE_MAX_SIZE;
     info->protected_raw_data_max_size = DEFAULT_PROTECTED_RAW_DATA_MAX_SIZE;
+    info->handle_alloc_stacktrace_limit = 0;
     info->protected_raw_data_size = 0;
     DHQueue_init(&info->open_handles);
     DHQueue_init(&info->closed_handles);