Apache Software Foundation
[S] Subversion

[You can also view the single-page version of this document.]

Debugging Subversion

Debugging with SVN_DBG

The SVN_DBG debugging tool is a C Preprocessor macro that sends debugging output to stdout (by default) or stderr whilst not interfering with the SVN test suite.

It provides an alternative to a debugger such as gdb, or alternatively, extra information to assist in the use of a debugger. It might be especially useful in situations where a debugger cannot be used.

The svn_debug module contains two debug aid macros that print the file:line of the call and printf-like arguments to the #SVN_DBG_OUTPUT stdio stream (#stdout by default):

SVN_DBG( ( const char *fmt, ...) ) /* double braces are neccessary */
and
SVN_DBG_PROPS( ( apr_hash_t *props, const char *header_fmt, ...) )

Controlling SVN_DBG output:

  • SVN_DBG is enabled whenever svn is configured with --enable-maintainer-mode.
  • The SVN test suite turns off SVN_DBG output automatically, to suppress the output manually, set the SVN_DBG_QUIET variable to 1 in your shell environment.
  • When you are done, please be sure to remove any instances of the SVN_DBG and SVN_DBG_PROPS macros from any code you are committing and from any patch that you send to the list. (AKA: Do not forget a scalpel in the patient!)

The SVN_DBG macro definitions and code are located in:

Sample patch showing usage of the SVN_DBG macro:

Index: subversion/libsvn_fs_fs/fs_fs.c
===================================================================
--- subversion/libsvn_fs_fs/fs_fs.c     (revision 1476635)
+++ subversion/libsvn_fs_fs/fs_fs.c     (working copy)
@@ -2303,6 +2303,9 @@ get_node_revision_body(node_revision_t **noderev_p
 
   /* First, try a cache lookup. If that succeeds, we are done here. */
   SVN_ERR(get_cached_node_revision_body(noderev_p, fs, id, &is_cached, pool));
+  SVN_DBG(("Getting %s from: %s\n", 
+           svn_fs_fs__id_unparse(id),
+           is_cached ? "cache" : "disk"));
   if (is_cached)
     return SVN_NO_ERROR;

Sample patch showing usage of the SVN_DBG_PROPS macro:

Index: subversion/svn/proplist-cmd.c
===================================================================
--- subversion/svn/proplist-cmd.c	(revision 1475745)
+++ subversion/svn/proplist-cmd.c	(working copy)
@@ -221,6 +221,7 @@ svn_cl__proplist(apr_getopt_t *os,
                                       URL, &(opt_state->start_revision),
                                       &rev, ctx, scratch_pool));
+      /*  this can be called with svn proplist  --revprop -r <rev> */
+      SVN_DBG_PROPS((proplist,"The variable apr_hash_t *proplist contains: "));
       if (opt_state->xml)
         {
           svn_stringbuf_t *sb = NULL;

Debugging the server

Debugging the DAV server

'mod_dav_svn.so' contains the main Subversion server logic; it runs as a module within mod_dav, which runs as a module within httpd. If httpd is probably using dynamic shared modules, you might need to set breakpoint pending on (in ~/.gdbinit) before setting breakpoints in mod_dav_svn would be possible. Alternatively, you may start httpd, interrupt it, set your breakpoint, and continue:

   % gdb httpd
   (gdb) run -X
   ^C
   (gdb) break some_func_in_mod_dav_svn
   (gdb) continue

The -X switch is equivalent to -DONE_PROCESS and -DNO_DETACH, which ensure that httpd runs as a single thread and remains attached to the tty, respectively. As soon as it starts, it sits and waits for requests; that's when you hit control-C and set your breakpoint.

You'll probably want to watch Apache's run-time logs

   /usr/local/apache2/logs/error_log
   /usr/local/apache2/logs/access_log

to help determine what might be going wrong and where to set breakpoints.

Alternatively, running ./subversion/tests/cmdline/davautocheck.sh --gdb in a working copy will start httpd using the mod_dav_svn in that working copy. You can then run individual Python tests against that: ./basic_tests.py --url=http://localhost:3691/.

Debugging the ra_svn client and server, on Unix

Bugs in ra_svn usually manifest themselves with one of the following cryptic error messages:

  svn: Malformed network data
  svn: Connection closed unexpectedly

(The first message can also mean the data stream was corrupted in tunnel mode by user dotfiles or hook scripts; see issue #1145.) The first message generally means you to have to debug the client; the second message generally means you have to debug the server.

It is easiest to debug ra_svn using a build with --disable-shared --enable-maintainer-mode. With the latter option, the error message will tell you exactly what line to set a breakpoint at; otherwise, look up the line number at the end of marshal.c:vparse_tuple() where it returns the "Malformed network data" error.

To debug the client, simply pull it up in gdb, set a breakpoint, and run the offending command:

  % gdb svn
  (gdb) break marshal.c:NNN
  (gdb) run ARGS
  Breakpoint 1, vparse_tuple (list=___, pool=___, fmt=___, 
    ap=___) at subversion/libsvn_ra_svn/marshal.c:NNN
  NNN                                 "Malformed network data");

There are several bits of useful information:

  • A backtrace will tell you exactly what protocol exchange is failing.

  • "print *conn" will show you the connection buffer. read_buf, read_ptr, and read_end represent the read buffer, which can show you the data the marshaller is looking at. (Since read_buf isn't generally 0-terminated at read_end, be careful of falsely assuming that there's garbage data in the buffer.)

  • The format string determines what the marshaller was expecting to see.

To debug the server in daemon mode, pull it up in gdb, set a breakpoint (usually a "Connection closed unexpectedly" error on the client indicates a "Malformed network data" error on the server, although it can also indicate a core dump), and run it with the "-X" option to serve a single connection:

  % gdb svnserve
  (gdb) break marshal.c:NNN
  (gdb) run -X

Then run the offending client command. From there, it's just like debugging the client.

Debugging the server in tunnel mode is more of a pain. You'll need to stick something like "{ int x = 1; while (x); }" near the top of svnserve's main() and put the resulting svnserve in the user path on the server. Then start an operation, gdb attach the process on the server, "set x = 0", and step through the code as desired.

Tracing network traffic

Tracing the network traffic between the client and the server can be helpful in debugging. There are several ways to go about doing a network trace (and this list is not exhaustive).

You may well want to disable compression when doing a network trace — see the http-compression parameter in the servers configuration file.

Network tracing with Wireshark

Use Wireshark (formerly known as "Ethereal") to eavesdrop on the conversation.

First, make sure that between captures within the same wireshark session, you hit Clear, otherwise filters from one capture (say, an HTTP capture) might interfere with others (say, an ra_svn capture).

Assuming you're cleared, then:

  1. Pull down the Capture menu, and choose Capture Filters.

  2. If debugging the http:// (WebDAV) protocol, then in the window that pops up, choose "HTTP TCP port (80)" (which should result in the filter string "tcp port http").

    If debugging the svn:// (ra_svn) protocol, then choose New, give the new filter a name (say, "ra_svn"), and type "tcp port 3690" into the filter string box.

    When done, click OK.

  3. Again go to the Capture menu, this time choose Interfaces, and click Options next to the appropriate interface (probably you want interface "lo", for "loopback", assuming the server will run on the same machine as the client).

  4. Turn off promiscuous mode by unchecking the appropriate checkbox.

  5. Click the Start button in the lower right to start the capture.

  6. Run your Subversion client.

  7. Click the Stop icon (a red X over an ethernet interface card) when the operation is finished (or Capture->Stop should work). Now you have a capture. It looks like a huge list of lines.

  8. Click on the Protocol column to sort.

  9. Then, click on the first relevant line to select it; usually this is just the first line.

  10. Right click, and choose Follow TCP Stream. You'll be presented with the request/response pairs of the Subversion client's HTTP conversion.

The above instructions are specific to the graphical version of Wireshark (version 0.99.6), and don't apply to the command-line version known as "tshark" (which corresponds to "tethereal", from back when Wireshark was called Ethereal).

Network tracing with neon-debug-mask

Alternatively, you may set the neon-debug-mask parameter in your servers configuration file to cause neon's debugging output to appear when you run the svn client. The numeric value of neon-debug-mask is a combination of the NE_DBG_... values in the header file ne_utils.h. For current versions of neon, setting neon-debug-mask to 130 (i.e. NE_DBG_HTTP+NE_DBG_HTTPBODY) will cause the HTTP data to be shown. Note that neon-debug-mask will only work if neon was compiled with debugging support.

Network tracing with socat

Another alternative is to set up a logging proxy between the Subversion client and server. A simple way to do this is to use the socat program. For example, to log communication with an svnserve instance, run the following command:

socat -v TCP-LISTEN:9630,reuseaddr,fork TCP4:localhost:svn

Then run your svn commands using an URL base of svn://127.0.0.1:9630/; socat will forward the traffic from port 9630 to the normal svnserve port (3690), and will print all traffic in both directions to standard error, prefixing it with < and > signs to show the direction of the traffic.

Network tracing with http-proxy

If you're debugging a http client/server setup you can use a web debugging proxy like Charles or Fiddler.

Once you've setup such a proxy you'll need to configure Subversion to use the proxy. This can be done with the http-proxy-host and http-proxy-port parameters in the servers configuration file. You can also specify the proxy on the command line with these options --config-option 'servers:global:http-proxy-host=127.0.0.1' --config-option 'servers:global:http-proxy-port=8888'.

Tracking down memory leaks

Our use of APR pools makes it unusual for us to have memory leaks in the strictest sense; all the memory we allocate will be cleaned up eventually. But sometimes an operation takes more memory than it should; for instance, a checkout of a large source tree should not use much more memory than a checkout of a small source tree. When that happens, it generally means we're allocating memory from a pool whose lifetime is too long.

If you have a favorite memory leak tracking tool, you can configure with --enable-pool-debug (which will make every pool allocation use its own malloc()), arrange to exit in the middle of the operation, and go to it. If not, here's another way:

  • Configure with --enable-pool-debug=verbose-alloc. Make sure to rebuild all of APR and Subversion so that every allocation gets file-and-line information.

  • Run the operation, piping stderr to a file. Hopefully you have lots of disk space.

  • In the file, you'll see lots of lines which look like:

        POOL DEBUG: [5383/1024] PCALLOC (      2763/      2763/      5419) \
        0x08102D48 "subversion/svn/main.c:612"                             \
        <subversion/libsvn_subr/auth.c:122> (118/118/0)
       

    What you care about most is the tenth field (the one in quotes), which gives you the file and line number where the pool for this allocation was created. Go to that file and line and determine the lifetime of the pool. In the example above, main.c:612 indicates that this allocation was made in the top-level pool of the svn client. If this were an allocation which was repeated many times during the course of an operation, that would indicate a source of a memory leak. The eleventh field (the one in brackets) gives the file and line number of the allocation itself.