Simple PDF crashes uwsgi

[mireq]

Hello, i have this set of packages:

$ pip freeze|grep -i "\(pikepdf\|z3c\)"
pikepdf==6.0.2
z3c.rml==4.2.0

This is my reportlab rml file rendered using z3c.rml:

<document filename="invoice.pdf" title="Invoice">
	<docinit></docinit>

	<template title="Invoice" pagesize="(21cm, 29.7cm)">
		<pageTemplate id="main">
			<frame id="first" x1="28" y1="48" width="540" height="766"/>
		</pageTemplate>
	</template>

	<stylesheet></stylesheet>

	<story>
		<para>Text</para>
	</story>
</document>

code to render PDF:

from z3c.rml import rml2pdf

with reportlab_mutex:
    return rml2pdf.parseString(rml_code)

Uwsgi runs with restricted number of requests like --max-requests 1000. This will restart worker after 1000 requests (mostly to prevent memory fragmentation).

This causes segmentation fault in shutdown phase of uwsgi. After crash in this phase uwsgi cannot handle any new request. Here is backtrace:

...The work of process 16020 is done. Seeya!
!!! uWSGI process 16021 got Segmentation Fault !!!
*** backtrace of 16021 ***
/usr/bin/uwsgi(uwsgi_backtrace+0x2f) [0x55cf61fe541f]
/usr/bin/uwsgi(uwsgi_segfault+0x23) [0x55cf61fe5863]
/lib64/libc.so.6(+0x3db30) [0x7f3e518ccb30]
/home/mirec/venv/lib/python3.9/site-packages/pikepdf/_qpdf.cpython-39-x86_64-linux-gnu.so(+0x3d651) [0x7f3e46cbb651]
/home/mirec/venv/lib/python3.9/site-packages/pikepdf/_qpdf.cpython-39-x86_64-linux-gnu.so(+0x40866) [0x7f3e46cbe866]
/home/mirec/venv/lib/python3.9/site-packages/pikepdf/_qpdf.cpython-39-x86_64-linux-gnu.so(+0x492b7) [0x7f3e46cc72b7]
/usr/lib64/libpython3.9.so.1.0(+0x102840) [0x7f3e4f102840]
/usr/lib64/libpython3.9.so.1.0(_PyGC_CollectNoFail+0x3e) [0x7f3e4f1c1f4e]
/usr/lib64/libpython3.9.so.1.0(Py_FinalizeEx+0x17a) [0x7f3e4f1c03fa]
/usr/bin/uwsgi(uwsgi_plugins_atexit+0x81) [0x55cf61fe1f21]
/lib64/libc.so.6(+0x401f8) [0x7f3e518cf1f8]
/lib64/libc.so.6(+0x4030a) [0x7f3e518cf30a]
/usr/bin/uwsgi(+0x35e6f) [0x55cf61f94e6f]
/usr/bin/uwsgi(simple_goodbye_cruel_world+0x59) [0x55cf61fe4d29]
/usr/bin/uwsgi(+0x85d68) [0x55cf61fe4d68]
/usr/bin/uwsgi(uwsgi_close_request+0x567) [0x55cf61f95d77]
/usr/bin/uwsgi(simple_loop_run+0xc2) [0x55cf61fe0cd2]
/usr/bin/uwsgi(simple_loop+0x7a) [0x55cf61fe0daa]
/usr/bin/uwsgi(uwsgi_ignition+0x296) [0x55cf61fe5bb6]
/usr/bin/uwsgi(uwsgi_worker_run+0x25c) [0x55cf61fea1dc]
/usr/bin/uwsgi(uwsgi_run+0x46a) [0x55cf61fea76a]
/usr/bin/uwsgi(+0x3282e) [0x55cf61f9182e]
/lib64/libc.so.6(+0x2934a) [0x7f3e518b834a]
/lib64/libc.so.6(__libc_start_main+0x7c) [0x7f3e518b83fc]
/usr/bin/uwsgi(_start+0x21) [0x55cf61f91851]
*** end of backtrace ***

[jbarlow83]

I'll need some information about how pikepdf is being used in this application. In particular it will be important to try to determine what objects are being accessed and retained.

It would also be helpful to know if you're able to reproduce this on pikepdf < 6.

The following produces nothing exciting:

def test_z3c():
    rml2pdf = pytest.importorskip("z3c.rml.rml2pdf")
    data = rml2pdf.parseString(XML)
    for _ in range(1000):
        with pikepdf.open(data) as pdf:
            pass
    gc.collect()

[mireq]

I am not processing PDF using pikepdf, i am not calling any function, there is only import in z3c.rml - https://github.com/zopefoundation/z3c.rml/blob/fe8a2d4c8cf1091318bd1d7144249b17dd007b0d/src/z3c/rml/page.py

This import crashes uwsgi with pikepdf 5.x and 6.x. I have not tested other versions. Here is minimal example:

mkdir crash
cd crash
wget https://github.com/pikepdf/pikepdf/files/9680822/web.tar.gz
tar -xvzf web.tar.gz
python3.9 -m venv venv
. ./venv/bin/activate
pip install uWSGI==2.0.20 z3c.rml==4.2.0 pikepdf==6.0.2 Django==4.1.1 six
cd web
uwsgi --master --plugin python39 --http :8000 --virtualenv ../venv/ --module web.wsgi --max-requests 1

Then open http://localhost:8000/ and press Ctrl+c to stop uwsgi (or press F5 cca 10 times until crashes). Uwsgi will crash in shutdown phase.

web.tar.gz

[jbarlow83]

Well... this will be fun.

uwsgi is a process supervisor so it interferes with all normal debugging tools. :|

valgrind as usual is helpful and better a real stack trace:

==254313== Invalid read of size 8
==254313==    at 0xE86AFE1: std::_Hashtable<std::type_index, std::pair<std::type_index const, pybind11::detail::type_info*>, std::allocator<std::pair<std::type_index const, pybind11::detail::type_info*> >, std::__detail::_Select1st, std::equal_to<std::type_index>, std::hash<std::type_index>, std::__detail::_Mod_range_hashing, std::__detail::_Default_ranged_hash, std::__detail::_Prime_rehash_policy, std::__detail::_Hashtable_traits<false, false, true> >::_M_find_before_node(unsigned long, std::type_index const&, unsigned long) const [clone .isra.0] (hashtable.h:1833)
==254313==    by 0xE86E759: std::_Hashtable<std::type_index, std::pair<std::type_index const, pybind11::detail::type_info*>, std::allocator<std::pair<std::type_index const, pybind11::detail::type_info*> >, std::__detail::_Select1st, std::equal_to<std::type_index>, std::hash<std::type_index>, std::__detail::_Mod_range_hashing, std::__detail::_Default_ranged_hash, std::__detail::_Prime_rehash_policy, std::__detail::_Hashtable_traits<false, false, true> >::_M_erase(std::integral_constant<bool, true>, std::type_index const&) [clone .isra.0] (hashtable.h:2203)
==254313==    by 0xE878198: erase (hashtable.h:938)
==254313==    by 0xE878198: erase (unordered_map.h:763)
==254313==    by 0xE878198: pybind11_meta_dealloc (class.h:216)
==254313==    by 0x530FB37: ??? (in /usr/lib/x86_64-linux-gnu/libpython3.10.so.1.0)
==254313==    by 0x52E6E2D: ??? (in /usr/lib/x86_64-linux-gnu/libpython3.10.so.1.0)
==254313==    by 0x52E8E94: Py_FinalizeEx (in /usr/lib/x86_64-linux-gnu/libpython3.10.so.1.0)

The corresponding allocation came from here:

==255614==    by 0xE8CD82A: pybind11::class_<std::vector<QPDFObjectHandle, std::allocator<QPDFObjectHandle> >, std::unique_ptr<std::vector<QPDFObjectHandle, std::allocator<QPDFObjectHandle> >, std::default_delete<std::vector<QPDFObjectHandle, std::allocator<QPDFObjectHandle> > > > > pybind11::bind_vector<std::vector<QPDFObjectHandle, std::allocator<QPDFObjectHandle> >, std::unique_ptr<std::vector<QPDFObjectHandle, std::allocator<QPDFObjectHandle> >, std::default_delete<std::vector<QPDFObjectHandle, std::allocator<QPDFObjectHandle> > > >>(pybind11::handle, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (stl_bind.h:492)

...which is pikepdf._ObjectList/std::vector<QPDFObjectHandle>. That seems to be quite consistent.

pybind11_meta_dealloc is responsible for cleaning up all C++ types registered with pybind11. It's likely this will turn out to be a pybind11 issue, although it may be related to the way that pikepdf monkeypatches its C++ class bindings. I think uwsgi may be at
least partly responsible in some way, since pikepdf exits cleanly.

Note the caveats in Py_FinalizeEx - uwsgi's method of canceling interpreters is not guaranteed to work on all C extensions:
https://docs.python.org/3/c-api/init.html?highlight=py_finalizeex#c.Py_FinalizeEx
(pybind11, however, is supposed to support this.)

My next step will be to try to find a minimal reproducible using pybind11 only.

[jbarlow83]

py::bind_vector<ObjectList>(m, "_ObjectList") is removed, py::bind_map<ObjectMap>(m, "_ObjectMapping") fails in a similar fashion. If both are removed, uwsgi restarts correctly. (However, this is an "invalid pikepdf" that would break the test suite and production code.) It's looking very much like there's a problem with how these bindings are cleaned up in pybind11.

The error occurs if bind_vector/map is used, regardless of whether the macro PYBIND11_MAKE_OPAQUE(ObjectList); is enabled as normal or commented out.

[jbarlow83]

Reproduced in a standalone project - this is a pybind11 issue.

[jbarlow83]

pybind/pybind11#4205