On 2021-04-21 21:35, Daniel Shahaf wrote:
> Rick van der Zwet wrote on Wed, Apr 21, 2021 at 16:10:57 +0200:
>> Hi,
>>
>> I debugging crashes within the Trac (https://trac.edgewall.org/) when using
>> the svn backend. The issue seems to be related to Apache Portable Runtime
>> (APR) pool memory management at Trac together with subversion SWIG python
>> bindings and libsvn.
>>
>> I am trying to run subverion with APR (lifetime) debugging enabled
>> (./configure --enable-pool-debug=all --enable-debug) to give more insights,
>> how-ever I got stuck with the basics.
>
> I assume the use of «all» as the argument to --enable-pool-debug is
> deliberate? I.e., that enabling fewer bitflags wouldn't suffice for
> your use-case?
Good observation, thanks. I will leave out the lifetime checking to find
out if the remaining tests give the required information:
--enable-pool-debug=yes --enable-pool-debug=verbose
--enable-pool-debug=owner --enable-pool-debug=verbose-alloc
>
>> First I tried 'svn' which completes fine:
>>
>> Next I tried 'svn help' which gives me apr_pool_integrity check [lifetime]
...
> Looking at that file (in apr-1.6.5, since you didn't mention
> a particular version):
apr-1.7.0, context is identical.
>
> 1597 static void apr_pool_check_integrity(apr_pool_t *pool)
> 1598 {
> 1599 /* Rule of thumb: use of the global pool is always
> 1600 * ok, since the only user is apr_pools.c. Unless
> 1601 * people have searched for the top level parent and
> 1602 * started to use that...
> 1603 */
> 1604 if (pool == global_pool || global_pool == NULL)
> 1605 return;
> 1606
> 1607 /* Lifetime
> 1608 * This basically checks to see if the pool being used is
> still
> 1609 * a relative to the global pool. If not it was previously
> 1610 * destroyed, in which case we abort().
> 1611 */
> 1612 #if (APR_POOL_DEBUG & APR_POOL_DEBUG_LIFETIME)
> 1613 if (!apr_pool_is_child_of(pool, global_pool)) {
> 1614 #if (APR_POOL_DEBUG & APR_POOL_DEBUG_VERBOSE_ALL)
> 1615 apr_pool_log_event(pool, "LIFE",
> 1616 __FILE__ ":apr_pool_integrity check
> [lifetime]", 0);
> 1617 #endif /* (APR_POOL_DEBUG & APR_POOL_DEBUG_VERBOSE_ALL) */
> 1618 abort();
> 1619 }
> 1620 #endif /* (APR_POOL_DEBUG & APR_POOL_DEBUG_LIFETIME) */
>
> The Subversion caller is error.c (frame #6), and it has a comment saying
> it deliberately uses a pool unrelated to the global pool:
>
> 69 /* Strictly speaking, this is a memory leak, since we're
> creating an
> 70 unmanaged, top-level pool and never destroying it. We do
> this
> 71 because this pool controls the lifetime of the thread-local
> 72 storage for error locations, and that storage must always
> be
> 73 available. */
Thanks, I missed this completely, makes sence why it would trigger the
apr_pool_check_integrity check.
>> Program received signal SIGABRT, Aborted.
>> 0x0000000801088c2a in thr_kill () from /lib/libc.so.7
>> (gdb) bt
>> #0 0x0000000801088c2a in thr_kill () from /lib/libc.so.7
>> #1 0x0000000801087084 in raise () from /lib/libc.so.7
>> #2 0x0000000800ffd279 in abort () from /lib/libc.so.7
>> #3 0x0000000800ea8a57 in apr_pool_check_integrity (pool=0x80174d640) at
>> memory/unix/apr_pools.c:1618
>> #4 0x0000000800ea8c3d in apr_pcalloc_debug (pool=0x80174d640, size=16,
>> file_line=0x800e7c683 "threadproc/unix/threadpriv.c:28") at
>> memory/unix/apr_pools.c:1795
>> #5 0x0000000800ebbe49 in apr_threadkey_private_create (key=0x800873998
>> <error_file_key>,
>> dest=0x80081d770 <null_threadkey_dtor>, pool=0x80174d640) at
>> threadproc/unix/threadpriv.c:28
>> #6 0x000000080081bd61 in locate_init_once (ignored_baton=0x0) at
>> subversion/libsvn_subr/error.c:77
>> #7 0x00000008007f6d4e in str_init_func_wrapper (init_baton=0x7fffffffcfb0)
>> at subversion/libsvn_subr/atomic.c:156
>> #8 0x00000008007f6bcd in init_once (global_status=0x800873990
>> <svn_error.locate.init_status>,
>> init_func=0x8007f6d30 <str_init_func_wrapper>,
>> init_baton=0x7fffffffcfb0) at subversion/libsvn_subr/atomic.c:71
>> #9 0x00000008007f6ce0 in svn_atomic__init_once_no_error
>> (global_status=0x800873990 <svn_error.locate.init_status>,
>> str_init_func=0x80081bd30 <locate_init_once>, baton=0x0) at
>> subversion/libsvn_subr/atomic.c:170
>> #10 0x000000080081bca7 in svn_error__locate (file=0x8007d85cd
>> "subversion/libsvn_subr/io.c", line=3988)
>> at subversion/libsvn_subr/error.c:128
>> #11 0x000000080082235d in svn_io_file_open (new_file=0x7fffffffd0e8,
>> fname=0x8017523c0 "/etc/subversion/servers",
>> flag=1, perm=4095, pool=0x80174d500) at subversion/libsvn_subr/io.c:3988
> ⋮
>> #18 0x000000000025cc7f in main (argc=2, argv=0x7fffffffdaa0) at
>> subversion/svn/svn.c:3325
>> (gdb)
>> ===================================================================================================================
>>
>>
>> I tried subversion 1.14.1 and subversion-trunk@1889032. Traces above are
>> generated using the subversion-trunk codebase.
>>
>> I have also the unittests of the Apache Portable Runtime (APR) on which the
>> relevant(?) ones completes successfully.
>>
>> How can I find out if a) I am looking at an potential issue within
>> subversion source code, b) whether the APR debugging is flagging this as a
>> false positive or c) something else?
>
> I don't have a recommended workaround off the top of my head, sorry.
I really liked the suggestions provided, they gave me the clearity I
needed with regards the lifetime debug flagging on 'svn help' output,
thanks!
FYI: I did some futher investigation on the specific problem within Trac
I was trying to fix and I am getting more hints by experimenting with
flags and combinations. If I compile APR (1.7.0) without debugging it
produces a coredump with some endless(?) recursion, see attached
gdb-output.txt for details. If I compile apr with
'--enable-pool-debug=yes', the program executes without errors,
to-be-continued. Since this is most likely not subversion related I
think is best discussed on different mailinglist.
>
> For future reference, your MUA hard-wrapped the various traces, which
> made them difficult to read. Please disable hard wrapping for such
> cases, or use attachments named *.txt.
Thanks for the feedback, was unaware of hard-wrapping bt my MUA
(roundcube), will try to prevent it in the future postings.
Cheers,
Rick[New LWP 100144]
[New LWP 100082]
[New LWP 100141]
Core was generated by `python trac/web/standalone.py -p 8000 --base-path /trac
--auto-reload -e /home/r'.
Program terminated with signal SIGSEGV, Segmentation fault.
(gdb) p pool
$1 = (apr_pool_t *) 0x804542028
(gdb) p pool.parent
$2 = (apr_pool_t *) 0x804542028
(gdb) p pool.sibling
$3 = (apr_pool_t *) 0x0
(gdb) p pool.child
$4 = (apr_pool_t *) 0x804542028
(gdb) bt
#0 0x0000000803f2fe69 in apr_pool_destroy (pool=0x804542028) at
memory/unix/apr_pools.c:987
987 run_cleanups(&pool->pre_cleanups);
[Current thread is 1 (LWP 100144)]
#0 0x0000000803f2fe69 in apr_pool_destroy (pool=0x804542028) at
memory/unix/apr_pools.c:987
#1 0x0000000803f2fea8 in apr_pool_destroy (pool=0x804542028) at
memory/unix/apr_pools.c:997
#2 0x0000000803f2fea8 in apr_pool_destroy (pool=0x804542028) at
memory/unix/apr_pools.c:997
...
#87032 0x0000000803f2fea8 in apr_pool_destroy (pool=0x804542028) at
memory/unix/apr_pools.c:997
#87033 0x0000000803f2fea8 in apr_pool_destroy (pool=0x804542028) at
memory/unix/apr_pools.c:997
#87034 0x0000000803f2fea8 in apr_pool_destroy (pool=0x804542028) at
memory/unix/apr_pools.c:997
#87035 0x0000000803fd861b in ?? () from /usr/local/lib/libsvn_fs_fs-1.so.0
#87036 0x0000000803e5581f in svn_fs_open2 () from
/usr/local/lib/libsvn_fs-1.so.0
#87037 0x0000000803fa8e56 in ?? () from /usr/local/lib/libsvn_repos-1.so.0
#87038 0x0000000803fa8cb5 in svn_repos_open3 () from
/usr/local/lib/libsvn_repos-1.so.0
#87039 0x00000008048d0d0d in _wrap_svn_repos_open () from
/usr/local/lib/python3.7/site-packages/libsvn/_repos.so
#87040 0x000000080036b7e7 in PyCFunction_Call () from
/usr/local/lib/libpython3.7m.so.1.0
#87041 0x0000000800429438 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87042 0x000000080042c758 in _PyEval_EvalCodeWithName () from
/usr/local/lib/libpython3.7m.so.1.0
#87043 0x000000080036b473 in _PyFunction_FastCallKeywords () from
/usr/local/lib/libpython3.7m.so.1.0
#87044 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87045 0x000000080042906c in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87046 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87047 0x000000080036c433 in _PyObject_Call_Prepend () from
/usr/local/lib/libpython3.7m.so.1.0
#87048 0x00000008003bd280 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87049 0x00000008003b8dd1 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87050 0x000000080036b2c2 in _PyObject_FastCallKeywords () from
/usr/local/lib/libpython3.7m.so.1.0
#87051 0x000000080042bddb in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87052 0x0000000800429108 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87053 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87054 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87055 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87056 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87057 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87058 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87059 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87060 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87061 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87062 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87063 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87064 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87065 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87066 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87067 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87068 0x000000080042c758 in _PyEval_EvalCodeWithName () from
/usr/local/lib/libpython3.7m.so.1.0
#87069 0x000000080036b473 in _PyFunction_FastCallKeywords () from
/usr/local/lib/libpython3.7m.so.1.0
#87070 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87071 0x000000080042906c in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87072 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87073 0x000000080036c433 in _PyObject_Call_Prepend () from
/usr/local/lib/libpython3.7m.so.1.0
#87074 0x00000008003bbdca in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87075 0x000000080036b2c2 in _PyObject_FastCallKeywords () from
/usr/local/lib/libpython3.7m.so.1.0
#87076 0x000000080042bddb in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87077 0x000000080042906c in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87078 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87079 0x000000080036c433 in _PyObject_Call_Prepend () from
/usr/local/lib/libpython3.7m.so.1.0
#87080 0x00000008003bbdca in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87081 0x000000080036b2c2 in _PyObject_FastCallKeywords () from
/usr/local/lib/libpython3.7m.so.1.0
#87082 0x000000080042bddb in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87083 0x0000000800429108 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87084 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87085 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87086 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87087 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87088 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87089 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87090 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87091 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87092 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87093 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87094 0x000000080036c433 in _PyObject_Call_Prepend () from
/usr/local/lib/libpython3.7m.so.1.0
#87095 0x00000008003bd280 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87096 0x00000008003b8dd1 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87097 0x000000080036b2c2 in _PyObject_FastCallKeywords () from
/usr/local/lib/libpython3.7m.so.1.0
#87098 0x000000080042bddb in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87099 0x000000080042906c in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87100 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87101 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87102 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87103 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87104 0x000000080036c433 in _PyObject_Call_Prepend () from
/usr/local/lib/libpython3.7m.so.1.0
#87105 0x000000080036b5d9 in PyObject_Call () from
/usr/local/lib/libpython3.7m.so.1.0
#87106 0x0000000800429348 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87107 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87108 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87109 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87110 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87111 0x000000080042bde2 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87112 0x0000000800429052 in _PyEval_EvalFrameDefault () from
/usr/local/lib/libpython3.7m.so.1.0
#87113 0x000000080036b954 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87114 0x000000080036c433 in _PyObject_Call_Prepend () from
/usr/local/lib/libpython3.7m.so.1.0
#87115 0x000000080036b5d9 in PyObject_Call () from
/usr/local/lib/libpython3.7m.so.1.0
#87116 0x00000008004b4cd8 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87117 0x0000000800469c49 in ?? () from /usr/local/lib/libpython3.7m.so.1.0
#87118 0x00000008005ecfac in ?? () from /lib/libthr.so.3
#87119 0x0000000000000000 in ?? ()
Backtrace stopped: Cannot access memory at address 0x7fffdf3fa000
