SVNServe processes/threads not being closed properly?

I have the latest version of TeamCity (as of this posting date) installed on OSX (leopard), projects and are all setup and running, I have an agent running on the same machine, it checks out my repository fine (agent checkout) and executes builds.

On the same osx machine I have SVNServe running (as SvnServe daemon, not apache or inetd). Initially I was using 1.5.5, but I've upgraded the server to 1.6.1 (IIRC - currently away from machine) and I still have the same problem...

Whenever teamcity checks for changes[1] svnserve seems to leave a process behind and eventually when I reach about 200 threads/processes teamcity fails because SVNServe won't allow any more handles to my repository files to be opened.(the file handle limit is currently 256 on my mac)

I was running svnserve happily on a linkstation, but when I started using teamcity that would eventually cause a crash and shutdown the system. I never tracked that particular issue down, but I can imagine it was a similar problem running out of memory/file handles etc.

I've been researching on google and the only thing I can find is that it might be the fault of Teamcity not sending the correct EOF signal to svn. I don't know the protocol, but this seems a reasonable fault of teamcity's...

I've not tested thoroughly, but SvnX and tortoise don't seem to be leaving behind processes when I checkout or check logs, only TeamCity.

Has anyone had similar experiences? Does anyone know of any bugs running teamcity, an agent, or SvnServe on OSX?
Is there anywhere deeper I can check?


[1] Same applies for checkouts etc, but I can just leave teamcity server checking for changes and it'll eventually fail.
[2] I've tried switching svnserve to be threaded and it's exactly the same behaviour

14 comments

Hello Graham,

   How did you configure SVNServe to be started? I want to reproduce the issue so I'd like to mirror your configuration.

  Regards,
  KIR

0

I've started it via a script, directly from a sh terminal, and from an apple script all with the same results.

svnserve -d --listen-port 1983 -r ~/MyRepos/
and
svnserve -d --listen-port 1983 --threads -r ~/MyRepos/

these are running on the 1.6.x package I've installed from opencollab (http://subversion.apache.org/packages.html#osx). I've not tested with 1.4.4 which is bundled with OSX as our repos was previously using 1.5.5.
Also note the server is running leopard, not snow leopard.

When I get home tonight I'm going to have a look with strace, and I will post any significant (svn) .conf details too if you'd like. Are there any team-city logs you'd like? (I can give you admin access to our team city if you like...)

0

Hello Graham,

   I've tried your configuration with TeamCity 5.1.2 - so far, it works for me.
   I use

svn, version 1.6.6 (r40053)
   compiled Oct 22 2009, 14:13:09
Copyright (C) 2000-2009 CollabNet.

   An access to your TeamCity installation would be great. You can send the credentials to kirill.maximov@.

   Also, how do you check the number of svnserve processes on your machine?

   It is rather unlikely that TeamCity leaves open connections to svn, it uses common approach for different types of repositories and always closes the connection.

   Regards,
   KIR

0

I check the Activity Monitor in osx and after 10 mins or so (3 VCS roots on 8 configurations, checking for updates every 60 secs) I have 200+ "svnserve" processes (or about 190 threads in threaded mode) and from then on SVN reports (via teamcity) that it cannot open any more handles to the ~/Repos/Format file

Your email is kirill.maximov at JetBrains dot net? (the domain was omitted)

I only make this assumption that it might be team city leaving it open because I read somewhere (wrongly or rightly) that the connection stays open server side if it's not yet recieved an EOF (not sure if this is a double-terminator, or a token, again, I don't know the svn protocol) and I've had this server going (albiet on a different machine, see GP) for weeks on end with no trouble, I start using teamcity and it has these problems... But if it's a file/protocol/socket issue, I'm sure it could be easily down to an OSX/OS configuration difference...

0

OK, I see than, thanks. Will try to hunt the problem in place.
My email ends with jetbrains.com.

KIR

0

Also, there is a possible workaround to run SVNserve via LaunchDaemon.
I attach a plist file which runs svnserve on my machine, with a couple of tweaks you can use it on yours.
This way, you'll have svnserve daemon running as needed.

This file should be put to /Library/LaunchDaemons directory and started as
sudo launchctl load /Library/LaunchDaemons/org.tigris.subversion.svnserve.plist

May be you'll find this approach interesting. Not sure, whether it would help, though.

KIR



Attachment(s):
org.tigris.subversion.svnserve.plist.zip
0

Hi Graham,

   Thanks for the access.

   The situation is rather interesting, because it is not reproducible on my side yet.

   Could you please send exact version of the SVN server you're using. If this is not the latest SVN server, please upgrade and see if the problem reproduces - may be this is not TeamCity's fault.

 

  Also, if you have some unusual svn configuration options, please let me know.

 

  Also, it may be helpful if you add --log-file=path/to/log option to svnserve daemon so we could collect some logs related to the problem.


  Thanks!
  KIR

0

My mistake, svnserve reboots fine. I might try the LaunchD but atm I can control it quite nicely from the dock (I've got an apple script to start and stop it).

Anyway, version

svnserve, version 1.6.11 (r934486)
   compiled Apr 20 2010, 17:01:38

Note, I originally had the problem with 1.5.5, and upgraded to 1.6.11 to see if that fixed it, so I'm guessing this isn't an svnserve bug-in-a-particular-version issue.


I have several repositories running from this root; (each created with svnadmin create). These are NOT directories underneath one repository. They allhave their own revisions.
~/Tootle/ (with trunk, branch, tags)
~/TestGame/
~/Rocket/
(and some others but those are the only ones setup in team city)
Which is why they have the checkout rules you can see in each configuration (so the svn information doesn't conflict, plus I need that setup to compile properly)

svnserve.conf is the same in each repository, other than changing the realm I think it's the default setup.

I am now running with this command line (directly into the terminal as you can see)
fry:~ graham$ /opt/subversion/bin/svnserve --daemon --listen-port 1983 -r ~/TootleRepository --foreground --log-file=SvnLog.txt


Teamcity is now running a build, collected changes okay (no fault atm because the server has only just started) and the initial log below;
There are now 57 processes called svnserve... (pids matching those in the log)

1747 2010-06-16T18:37:54.155268Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1747 2010-06-16T18:37:54.208486Z 86.16.22.183 Teamcity Tootle get-latest-rev
1748 2010-06-16T18:37:54.221055Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1749 2010-06-16T18:37:54.235053Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1750 2010-06-16T18:37:54.250152Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1761 2010-06-16T18:38:47.521044Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1761 2010-06-16T18:38:47.524221Z 86.16.22.183 Teamcity TestGame get-latest-rev
1762 2010-06-16T18:38:47.535934Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1763 2010-06-16T18:38:47.551090Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1764 2010-06-16T18:38:47.565196Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1765 2010-06-16T18:38:47.805649Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1765 2010-06-16T18:38:47.808012Z 86.16.22.183 Teamcity TestGame get-latest-rev
1766 2010-06-16T18:38:47.819550Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1766 2010-06-16T18:38:47.821868Z 86.16.22.183 Teamcity Tootle get-latest-rev
1767 2010-06-16T18:38:47.839930Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1768 2010-06-16T18:38:47.875429Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1769 2010-06-16T18:38:47.888941Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1770 2010-06-16T18:38:47.903833Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1773 2010-06-16T18:38:49.919298Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1774 2010-06-16T18:38:50.075314Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1774 2010-06-16T18:38:50.077728Z 86.16.22.183 Teamcity TestGame get-latest-rev
1775 2010-06-16T18:38:50.090209Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1775 2010-06-16T18:38:50.096242Z 86.16.22.183 Teamcity TestGame check-path /@337
1776 2010-06-16T18:38:50.768994Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1777 2010-06-16T18:38:50.782967Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1778 2010-06-16T18:38:50.828503Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1778 2010-06-16T18:38:51.006841Z 86.16.22.183 Teamcity TestGame update / r337 depth=infinity
1780 2010-06-16T18:38:52.122278Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1781 2010-06-16T18:38:52.136835Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1781 2010-06-16T18:38:52.139456Z 86.16.22.183 Teamcity Tootle get-latest-rev
1782 2010-06-16T18:38:52.150457Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1782 2010-06-16T18:38:52.152960Z 86.16.22.183 Teamcity Tootle check-path /trunk@923
1779 2010-06-16T18:38:52.193923Z 86.16.22.183 Teamcity Rocket open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1779 2010-06-16T18:38:52.290869Z 86.16.22.183 Teamcity Rocket get-latest-rev
1783 2010-06-16T18:38:52.303094Z 86.16.22.183 Teamcity Rocket open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1784 2010-06-16T18:38:52.316637Z 86.16.22.183 Teamcity Rocket open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1785 2010-06-16T18:38:52.330231Z 86.16.22.183 Teamcity Rocket open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1787 2010-06-16T18:38:57.077634Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1787 2010-06-16T18:38:57.080308Z 86.16.22.183 Teamcity Tootle get-latest-rev
1788 2010-06-16T18:38:57.093865Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1789 2010-06-16T18:38:57.108748Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1790 2010-06-16T18:38:57.126225Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1792 2010-06-16T18:39:00.367688Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1793 2010-06-16T18:39:00.379686Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1794 2010-06-16T18:39:00.394240Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
1794 2010-06-16T18:39:01.903296Z 86.16.22.183 Teamcity Tootle update /trunk r923 depth=infinity
2011 2010-06-16T18:39:52.640341Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
2011 2010-06-16T18:39:52.711023Z 86.16.22.183 Teamcity TestGame get-latest-rev
2012 2010-06-16T18:39:52.722869Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
2014 2010-06-16T18:39:52.991909Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
2016 2010-06-16T18:39:53.100939Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
2040 2010-06-16T18:39:57.107558Z 86.16.22.183 Teamcity Rocket open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
2040 2010-06-16T18:39:57.133185Z 86.16.22.183 Teamcity Rocket get-latest-rev
2041 2010-06-16T18:39:57.145379Z 86.16.22.183 Teamcity Rocket open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
2042 2010-06-16T18:39:57.158973Z 86.16.22.183 Teamcity Rocket open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
2043 2010-06-16T18:39:57.173102Z 86.16.22.183 Teamcity Rocket open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
2074 2010-06-16T18:40:02.168762Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
2074 2010-06-16T18:40:02.242292Z 86.16.22.183 Teamcity Tootle get-latest-rev
2075 2010-06-16T18:40:02.276656Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
2076 2010-06-16T18:40:02.344676Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
2077 2010-06-16T18:40:03.893475Z 86.16.22.183 Teamcity Tootle open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) /trunk - -
0

And now it's gone down. Teamcity's error is "svn: Handshake failed, received: '' "

The last entries in the log are;

2437 2010-06-16T18:55:03.570974Z 86.16.22.183 Teamcity Rocket open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
1744 2010-06-16T18:55:08.522494Z 86.16.22.183 - - ERR subversion/svnserve/main.c 827 35 apr_proc_fork: Resource temporarily unavailable
2438 2010-06-16T18:56:03.555590Z 86.16.22.183 Teamcity TestGame open 2 cap=(edit-pipeline svndiff1 absent-entries depth mergeinfo log-revprops) / - -
2438 2010-06-16T18:56:03.557324Z 86.16.22.183 Teamcity TestGame get-latest-rev
1744 2010-06-16T18:56:03.562015Z 86.16.22.183 - - ERR subversion/svnserve/main.c 827 35 apr_proc_fork: Resource temporarily unavailable
1744 2010-06-16T18:56:08.548931Z 86.16.22.183 - - ERR subversion/svnserve/main.c 827 35 apr_proc_fork: Resource temporarily unavailable



(then many more with the same string)


I was going to open a TTY to do an strace, but I get this error when the server gets stuck;

Could not open a new pseudo-tty.

I presume this is just a resource problem with files being stuck open...
0

Hello Graham,

   I've installed the same version of SVN locally (but on the Snow Leopard). So far, I cannot reproduce the problem. The processes are started (I see this in logs), but finished quickly.

  On the server, I see you have some specific SVN configuration directories, for each VCS root. Why do you use them? Do you use any non-standard options for starting the server?

  Regards,
  KIR

0

Nothing non-standard other than the port. You can see the command line above.

I have individual repositories running from one svnserve (one repos root). This seems to run fine, I'm pretty sure it's a standard way of setting things up (been running happily for 2 years)

I simply use this line to create a new repos;

svnadmin create ~/TootleRepos/$repos

and duplicate the svnserve.conf which I've attached

Is there any other ways I can debug svnserve (other than building it myself and debugging...) to see what's happening on each process/thread?


Attachment(s):
svnserve.conf.zip
0

This is the "Sample" output from Activity Monitor in OSX of the first PID (presumably the main process)

Sampling process 6027 for 3 seconds with 1 millisecond of run time between samples
Sampling completed, processing symbols...
Analysis of sampling svnserve (pid 6027) every 1 millisecond
Call graph:
    2504 Thread_2507
      2504 start
        2504 main
          2504 accept
            2504 accept

Total number in stack (recursive counted multiple, when >=5):

Sort by top of stack, same collapsed (when >= 5):
        accept        2504
Sample analysis of process 6027 written to file /dev/stdout








And this is a random other process. They all seem to have the same call stack....


Sampling process 6079 for 3 seconds with 1 millisecond of run time between samples
Sampling completed, processing symbols...
Analysis of sampling svnserve (pid 6079) every 1 millisecond
Call graph:
    2266 Thread_2507
      2266 start
        2266 main
          2266 serve
            2266 svn_ra_svn_handle_commands2
              2266 svn_ra_svn_read_tuple
                2266 svn_ra_svn_read_item
                  2266 readbuf_getchar_skip_whitespace
                    2266 readbuf_getchar
                      2266 readbuf_fill
                        2266 readbuf_input
                          2266 svn_ra_svn__stream_read
                            2266 svn_stream_read
                              2266 sock_read_cb
                                2266 read
                                  2266 read

Total number in stack (recursive counted multiple, when >=5):

Sort by top of stack, same collapsed (when >= 5):
        read        2266
Sample analysis of process 6079 written to file /dev/stdout

0

Hello Graham,

  I suppose your system has some kind of proxy or some kind of middle man like that. Or there is some specific processing of the svn port you're using.

  I think so, because I've changed the hostname in the svn path in your VCS roots to 'localhost', and after that the problem has disappeared completely.

  But, there are still ESTABLISHED svnserve connections to some address ....know.cable.virginmedia.com, which are not terminated. These connections have apeared when I run checking for changes with old svn address.

  In your setup I created 2 build configurations, one runs netstat, another runs lsof, just to see what's going on.

  I believe the problem is not related to TeamCity, otherwise we'd see the same hangs for localhost address as well, I think.

  Best regards,
  KIR

0

I hadn't thought of that at all! There are 2 middle men (maybe 3 technically including the modem).

I use dyndns to forward XXXX.getmyip.com to my router, and the router is port-forwarding (1983 to fry.local). XXX.know.cable.virginmedia.co is my hostname on my internet connection (ie. the modem's hostname)

As you can see I normally use xxxx.Getmyip.com internally (even when the machines are on the same LAN or even same machine) just to make sure the external domain is working for others,
I do this with svnx, tortoiseSvn etc with no problem...

Thanks for tracking all this down, I'll use localhost for now and do a bit more investigation as to which part is causing this problem, as I believe there is still a problem, (again, other svn clients don't have a problem using the external hostname to access) but where blame lies is maybe a little unclear now. :)
I wouldn't want the problem to come up again if I move the svn server to another machine, or move team city...

I'll check the localhost name is fully working when I get home tonight/tomorrow

Thanks again

0

Please sign in to leave a comment.