[PATCH] dav_svn__update_report - svn_repos_abort_report closes invalid tempfile handle

Hi,

My company uses Subversion via Apache on a Windows Server 2003 R2 machine:

Apache/2.2.17 (Win32) mod_ssl/2.2.17 OpenSSL/0.9.8o SVN/1.6.16 DAV/2
mod_perl/2.0.4-dev Perl/v5.10.1

We're using version 1.6.16 of the Windows binaries from alagazam.net.

Our Apache logs showed that our server was occasionally failing:

[Tue Apr 19 20:33:30 2011] [notice] Parent: child process exited with
status 128 -- Restarting.

To track down the source of the exiting child processes, we attached a
debugger to the Apache child process. Eventually, an exception
occurred:

EXCEPTION_RECORD: ffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 7c8285f3 (ntdll!KiRaiseUserExceptionDispatcher+0x00000037)
  ExceptionCode: c0000008 (Invalid handle)
 ExceptionFlags: 00000000
NumberParameters: 0

The debugger helpfully pointed to the stack trace of the suspect thread:

ntdll!KiRaiseUserExceptionDispatcher+0x37
ntdll!KiFastSystemCall+0x3
ntdll!ZwClose+0xc
kernel32!CloseHandle+0x59
libapr_1!thread_mutex_cleanup+0x2c [.\locks\win32\thread_mutex.c @ 35]
libapr_1!apr_pool_cleanup_run+0x19 [.\memory\unix\apr_pools.c @ 2299]
libapr_1!apr_thread_mutex_destroy+0x14 [.\locks\win32\thread_mutex.c @ 133]
libapr_1!apr_file_close+0x2f [.\file_io\win32\open.c @ 501]
libsvn_subr_1!svn_io_file_close+0x1b
[C:\SVN\src-1.6.16\subversion\libsvn_subr\io.c @ 2694]
libsvn_repos_1!svn_repos_abort_report+0x12
[C:\SVN\src-1.6.16\subversion\libsvn_repos\reporter.c @ 1343]
mod_dav_svn!dav_svn__update_report+0xea1
[C:\SVN\src-1.6.16\subversion\mod_dav_svn\reports\update.c @ 1495]
mod_dav_svn!deliver_report+0x6f
[C:\SVN\src-1.6.16\subversion\mod_dav_svn\version.c @ 953]
mod_dav!dav_method_report+0xc4
[C:\local0\asf\release\build-2.2.17\modules\dav\main\mod_dav.c @ 4066]
mod_dav!dav_handler+0x1d4
[C:\local0\asf\release\build-2.2.17\modules\dav\main\mod_dav.c @ 4701]
libhttpd!ap_run_handler+0x21 [.\server\config.c @ 158]
libhttpd!ap_invoke_handler+0xb0 [.\server\config.c @ 376]
libhttpd!ap_process_request+0x3e [.\modules\http\http_request.c @ 286]
libhttpd!ap_process_http_connection+0x4c [.\modules\http\http_core.c @ 190]
libhttpd!ap_run_process_connection+0x21 [.\server\connection.c @ 43]
libhttpd!ap_process_connection+0x33 [.\server\connection.c @ 190]
libhttpd!worker_main+0x9c [.\server\mpm\winnt\child.c @ 778]
msvcrt!_endthreadex+0xa3
kernel32!BaseThreadStart+0x34

In libsvn_repos_1!svn_repos_abort_report, I see that it tried to close
a temporary file:

// line 1346 of libsvn_repos\reporter.c.
return svn_io_file_close(b->tempfile, pool);

Going up the call stack, I see how svn_repos_abort_report was called
in dav_svn__update_report:

// Line 1492 of mod_dav_svn\reports\update.c:
if (derr && rbaton)
   svn_error_clear(svn_repos_abort_report(rbaton, resource->pool));

Backtracing through dav_svn__update_report and considering when rbaton
could be non-null, I focused on the following call:

// Line 1379 of mod_dav_svn\reports\update.c:
serr = svn_repos_finish_report(rbaton, resource->pool);

Lo and behold, I noticed the following lines in svn_repos_finish_report:

// Line 1334 of libsvn_repos\reporter.c:
finish_err = finish_report(b, pool);
close_err = svn_io_file_close(b->tempfile, pool);

I suspect I have found the source of the invalid handle exception. The
handle to the tempfile pointed to by b->tempfile is being closed two
times. This only happens when the finish_report function returns any
kind of error.

To recap the code flow:

1. mod_dav_svn!dav_svn__update_report is called

2. mod_dav_svn!dav_svn__update_report calls
libsvn_repos_1!svn_repos_finish_report

3. libsvn_repos_1!svn_repos_finish_report calls libsvn_repos_1!finish_report

4. libsvn_repos_1!finish_report returns an error to
libsvn_repos_1!svn_repos_finish_report

5. libsvn_repos_1!svn_repos_finish_report calls
libsvn_subr_1!svn_io_file_close on a tempfile. The file successfully
closes and the handle to the tempfile is now invalid.

6. libsvn_repos_1!svn_repos_finish_report returns an error to
mod_dav_svn!dav_svn__update_report

7. mod_dav_svn!dav_svn__update_report jumps to the cleanup label.
Notice that the rbaton local variable wasn’t set to null.

8. mod_dav_svn!dav_svn__update_report calls
libsvn_repos_1!svn_repos_abort_report because rbaton are derr aren’t
both null

9. libsvn_repos_1!svn_repos_abort_report calls
libsvn_subr_1!svn_io_file_close on the same tempfile in step 5.

10. An invalid handle exception later occurs.

I see the problem was first noticed years ago on the mailing list
("When to call svn_repos_abort_report?"):

http://svn.haxx.se/dev/archive-2005-07/1176.shtml

However, that thread discusses calls to svn_repos_abort_report from
functions other than dav_svn__update_report.

I believe setting rbaton to NULL immediately after the call to
libsvn_repos_1!svn_repos_finish_report would eliminate the invalid
handle exception. I’m not sure if this is the most elegant solution.
See the attached patch.

[[[
Fix invalid handle exception when temporary file is closed multiple times.
]]]

Thanks,

Chad Nouis
Trapeze Group / www.trapezegroup.com