crash in apr_pool_destroy when accessing non-existing file in version control browser

[rickvanderzwet@…]

When I run tracd and request a non-existing file from the repository, the application crashes:

Server:

$ cat <<EOF > gdbcmds.txt
set height 0
set breakpoint pending on
run  trac/web/standalone.py  -p 8000  --base-path /trac -e ~/tracenvs
backtrace
quit
EOF

PYTHONPATH=.  gdb /usr/local/bin/python3.8 -x gdbcmds.txt -batch

Client: ab -n3 http://172.26.128.54:8000/trac/bar/export/1/second.txt

Coredump (full log in attachment:typescript-coredump-backtrace.txt​)

Server starting in PID 77461.
Serving on 0.0.0.0:8000 view at http://127.0.0.1:8000/trac
Using HTTP/1.1 protocol version
[New LWP 101056 of process 77461]
172.26.140.136 - - [27/Apr/2021 00:29:10] "GET /trac/bar/export/1/second.txt HTTP/1.0" 404 -
[LWP 101056 of process 77461 exited]
[New LWP 101058 of process 77461]
172.26.140.136 - - [27/Apr/2021 00:29:16] "GET /trac/bar/export/1/second.txt HTTP/1.0" 404 -
[LWP 101058 of process 77461 exited]
[New LWP 101057 of process 77461]

Thread 4 received signal SIGSEGV, Segmentation fault.
[Switching to LWP 101057 of process 77461]
0x00000008043b6478 in run_cleanups (cref=<error reading variable: Cannot access memory at address 0x7fffdf3fbff8>) at memory/unix/apr_pools.c:2624
2624    {
#0  0x00000008043b6478 in run_cleanups (cref=<error reading variable: Cannot access memory at address 0x7fffdf3fbff8>) at memory/unix/apr_pools.c:2624
#1  0x00000008043b5e6e in apr_pool_destroy (pool=0x8044f5028) at memory/unix/apr_pools.c:987
#2  0x00000008043b5ea8 in apr_pool_destroy (pool=0x8044f5028) at memory/unix/apr_pools.c:997
#3  0x00000008043b5ea8 in apr_pool_destroy (pool=0x8044f5028) at memory/unix/apr_pools.c:997
#4  0x00000008043b5ea8 in apr_pool_destroy (pool=0x8044f5028) at memory/unix/apr_pools.c:997
#5  0x00000008043b5ea8 in apr_pool_destroy (pool=0x8044f5028) at memory/unix/apr_pools.c:997
#6  0x00000008043b5ea8 in apr_pool_destroy (pool=0x8044f5028) at memory/unix/apr_pools.c:99

If I compile apr with --enable-pool-concurrency-check the following error is shown when I request the URL (first hit) (full log in attachment:typescript-with-apr-pool-concurrenty-check.txt​]:

Server starting in PID 58551.
Serving on 0.0.0.0:8000 view at http://127.0.0.1:8000/trac
Using HTTP/1.1 protocol version
[New LWP 100421 of process 58551]
172.26.140.136 - - [27/Apr/2021 00:26:51] "GET /trac/bar/export/1/second.txt HTTP/1.0" 404 -
pool concurrency check: pool 0x8044f5028((null)), thread cur 802d09c00 in use by 802d09c00, state destroyed -> in use 

Thread 2 received signal SIGABRT, Aborted.
[Switching to LWP 100421 of process 58551]
0x00000008008d5c2a in thr_kill () from /lib/libc.so.7
#0  0x00000008008d5c2a in thr_kill () from /lib/libc.so.7
#1  0x00000008008d4084 in raise () from /lib/libc.so.7
#2  0x000000080084a279 in abort () from /lib/libc.so.7
#3  0x00000008043b7cb1 in pool_concurrency_abort (pool=0x8044f5028, new=1, old=2) at memory/unix/apr_pools.c:768
#4  0x00000008043b6433 in pool_concurrency_set_used (pool=0x8044f5028) at memory/unix/apr_pools.c:778
#5  0x00000008043b5fb7 in apr_pool_destroy (pool=0x8044f5028) at memory/unix/apr_pools.c:989
#6  0x0000000804619097 in _wrap_apr_pool_destroy (self=<module at remote 0x805449b30>, args=(<apr_pool_t(this=<SwigPyObject at remote 0x80388a210>, _parent_pool=<apr_pool_t(this=<SwigPyObject at remote 0x80388a540>, _weakparent=<weakref at remote 0x803884680>, _apr_pool_destroy=<built-in method apr_pool_destroy of module object at remote 0x805449b30>, _svn_swig_py_clear_application_pool=<built-in method svn_swig_py_clear_application_pool of module object at remote 0x805449b30>) at remote 0x80388a3d0>, _weakparent=<weakref at remote 0x805437680>, _is_valid=<function at remote 0x804b6adc0>, _apr_pool_destroy=<built-in method apr_pool_destroy of module object at remote 0x805449b30>, _svn_swig_py_clear_application_pool=<built-in method svn_swig_py_clear_application_pool of module object at remote 0x805449b30>) at remote 0x80564faf0>,)) at subversion/bindings/swig/python/core.c:4034
...

I was able to find a work-around to prevent it from happening, how-ever I do not know why this actually fixes it and whether this is the correct place to fix it:

Index: tracopt/versioncontrol/svn/svn_fs.py
===================================================================
--- tracopt/versioncontrol/svn/svn_fs.py	(revision 17527)
+++ tracopt/versioncontrol/svn/svn_fs.py	(working copy)
@@ -686,6 +686,7 @@
                 raise NoSuchNode(path, rev, exception_to_unicode(e)) from e
         node_type = fs.check_path(self.root, self._scoped_path_utf8, pool)
         if node_type not in _kindmap:
+            pool.destroy()
             raise NoSuchNode(path, rev)
         cp_utf8 = fs.node_created_path(self.root, self._scoped_path_utf8, pool)
         cp = _from_svn(cp_utf8)

Version information of my development system:

$ svn --version
svn, version 1.14.1 (r1886195)
   compiled Apr 21 2021, 12:19:02 on amd64-portbld-freebsd12.2

$ python --version
Python 3.8.9

$ pkg info | grep -e apr -e serf -e subversion -e python
apr-1.7.0.1.6.1_1              Apache Portability Library
py38-subversion-1.14.1_2       Python bindings for version control system
python-3.8_3,2                 "meta-port" for the default version of Python interpreter
python3-3_3                    The "meta-port" for version 3 of the Python interpreter
python38-3.8.9                 Interpreted object-oriented programming language
serf-1.3.9_6                   Serf HTTP client library
subversion-1.14.1              Version control system

$ uname -a
FreeBSD hbsd122 12.2-RELEASE FreeBSD 12.2-RELEASE r366954 GENERIC  amd64

[Jun Omae]

Thanks for the reporting and investigating! Reproduced it on my environment (Python 3.9.4, Linux).

I try to verify the patch and fix it.

Thread 2 "python" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff296f700 (LWP 7712)]
0x00007fffe84b8dd6 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:799
799     /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c: No such file or directory.
(gdb) bt
#0  0x00007fffe84b8dd6 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:799
#1  0x00007fffe84b8e15 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:811
#2  0x00007fffe84b8e15 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:811
#3  0x00007fffe84b8e15 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:811
#4  0x00007fffe84b8e15 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:811
#5  0x00007fffe84b8e15 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:811
...
#174384 0x00007fffe84b8e15 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:811
#174385 0x00007fffe84b8e15 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:811
#174386 0x00007fffe84b8e15 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:811
#174387 0x00007fffe84b8e15 in apr_pool_destroy (pool=0x7ffff7e91028) at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:811
#174388 0x00007fffe84b8e15 in apr_pool_destroy (pool=pool@entry=0x7ffff7e91028)
    at /build/apr-jfvVat/apr-1.5.2/memory/unix/apr_pools.c:811
#174389 0x00007fffe78e3dc5 in fs_open (fs=0x7ffff7e92050, path=0x7ffff7e975d0 "REVPROP", common_pool_lock=0x7ffff7e950a0,
    scratch_pool=<optimized out>, common_pool=0x7ffff7e95028) at subversion/libsvn_fs_fs/fs.c:442
#174390 0x00007fffe896c52d in svn_fs_open2 (fs_p=fs_p@entry=0x7ffff7e97550, path=0x7ffff7e975d0 "REVPROP",
    fs_config=fs_config@entry=0x0, result_pool=result_pool@entry=0x7ffff7e97028, scratch_pool=scratch_pool@entry=0x7ffff7e97028)
    at subversion/libsvn_fs/fs-loader.c:561
#174391 0x00007fffe5ecad19 in get_repos (repos_p=repos_p@entry=0x7ffff296bb00,
    path=path@entry=0x7fffe40fa210 "/home/jun66j5/var/svn/svnrepos", exclusive=exclusive@entry=0, nonblocking=nonblocking@entry=0,
    open_fs=open_fs@entry=1, fs_config=fs_config@entry=0x0, result_pool=0x7ffff7e97028, scratch_pool=0x7ffff7e97028)
    at subversion/libsvn_repos/repos.c:1311
#174392 0x00007fffe5ecb9e9 in svn_repos_open3 (repos_p=repos_p@entry=0x7ffff296bb00,
    path=path@entry=0x7fffe40fa210 "/home/jun66j5/var/svn/svnrepos", fs_config=fs_config@entry=0x0,
    result_pool=result_pool@entry=0x7ffff7e97028, scratch_pool=scratch_pool@entry=0x7ffff7e97028)
    at subversion/libsvn_repos/repos.c:1375
#174393 0x00007fffe5eb47f8 in svn_repos_open2 (repos_p=repos_p@entry=0x7ffff296bb00,
    path=path@entry=0x7fffe40fa210 "/home/jun66j5/var/svn/svnrepos", fs_config=fs_config@entry=0x0, pool=pool@entry=0x7ffff7e97028)
    at subversion/libsvn_repos/deprecated.c:151
#174394 0x00007fffe5eb480a in svn_repos_open (repos_p=repos_p@entry=0x7ffff296bb00,
    path=path@entry=0x7fffe40fa210 "/home/jun66j5/var/svn/svnrepos", pool=pool@entry=0x7ffff7e97028)
    at subversion/libsvn_repos/deprecated.c:159
#174395 0x00007fffe51742f3 in _wrap_svn_repos_open (self=<optimized out>,
    args=(b'/home/jun66j5/var/svn/svnrepos', <apr_pool_t(this=<SwigPyObject at remote 0x7fffe40cff60>, _parent_pool=<apr_pool_t(this=<SwigPyObject at remote 0x7fffe58f37b0>, _parent_pool=None, _weakparent=None, _is_valid=<function at remote 0x7fffe590c4c0>, _apr_pool_destroy=<built-in method apr_pool_destroy of module object at remote 0x7fffe5bd21d0>, _svn_swig_py_clear_application_pool=<built-in method svn_swig_py_clear_application_pool of module object at remote 0x7fffe5bd21d0>) at remote 0x7fffe58f37f0>, _weakparent=<weakref at remote 0x7fffe40619f0>, _is_valid=<function at remote 0x7fffe514d670>, _apr_pool_destroy=<built-in method apr_pool_destroy of module object at remote 0x7fffe5bd21d0>, _svn_swig_py_clear_application_pool=<built-in method svn_swig_py_clear_application_pool of module object at remote 0x7fffe5bd21d0>) at remote 0x7fffe40cf6a0>)) at subversion/bindings/swig/python/svn_repos.c:4691
#174396 0x00000000005efe08 in cfunction_call () at ../Objects/methodobject.c:548
#174397 0x000000000050da44 in _PyObject_Call () at ../Objects/call.c:281
...
#174601 _PyObject_Call (tstate=<optimized out>, callable=<method at remote 0x7ffff2b9d180>, args=(), kwargs=<optimized out>)
    at ../Objects/call.c:266
#174602 0x00000000006684a3 in t_bootstrap () at ../Modules/_threadmodule.c:1040
#174603 0x0000000000645834 in pythread_wrapper (arg=<optimized out>) at ../Python/thread_pthread.h:236
#174604 0x00007ffff7bc16ba in start_thread (arg=0x7ffff296f700) at pthread_create.c:333
#174605 0x00007ffff6da44dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

[Jun Omae]

Proposed changes in [e3d93c09/jomae.git] (jomae.git@t13401).

The pool of SubversionNode should be marked as invalid when the pool of SubversionRepository is destroyed via gc.collect(), however it is destroyed doubly due to not marked.

In the changes, SubversionNode.__del__ destroys explicitly the pool in order to avoid the issue.

[Jun Omae]

Revised branch jomae.git@t13401.

[Ryan J Ollos]

Tests pass for me with Python 3.9.4 on macOS.

[Jun Omae]

Thanks for the testing. Committed in [17529].

The issue has been fixed in subversion@trunk (and will be fixed in 1.14.2).

See also:

• ​https://svn.apache.org/r1889487
• ​https://bugs.python.org/issue40312