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
Index: subversion/mod_dav_svn/reports/update.c
===================================================================
--- subversion/mod_dav_svn/reports/update.c (revision 1095513)
+++ subversion/mod_dav_svn/reports/update.c (working copy)
@@ -1317,6 +1317,11 @@ dav_svn__update_report(const dav_resource *resourc
/* this will complete the report, and then drive our editor to generate
the response to the client. */
serr = svn_repos_finish_report(rbaton, resource->pool);
+
+ /* We're finished with the report baton. Note that so we don't try
+ to abort this report later. */
+ rbaton = NULL;
+
if (serr)
{
derr = dav_svn__convert_err(serr, HTTP_INTERNAL_SERVER_ERROR,
@@ -1326,10 +1331,6 @@ dav_svn__update_report(const dav_resource *resourc
goto cleanup;
}
- /* We're finished with the report baton. Note that so we don't try
- to abort this report later. */
- rbaton = NULL;
-
/* ### Temporarily disable resource_walks for single-file switch
operations. It isn't strictly necessary. */
if (dst_path && resource_walk)
