FastCGI : timeout during project index the first time after starting Trac

[jouvin@…]

When running Trac as FastCGI, I get an 'internal server error' the first time I asked for Trac project index (no project name specified). The only thing to do is to wait 30 seconds or 1 minute more and retry. This happens every time the trac.fcgi is restarted (no matter if Apache is also restared or not). This looks like a too short time out. I was not able to find any relevant parameter in Apache configuration but probably I just missed something...

I get exactly the same problem with source browser the first time I launch it in a project with a large repository.

Michel

[anonymous]

Sorry for entering the wrong version... In fact this issue already happened in the source browser in 0.9.x...

[mgood]

Can you retest this since r3677 and r3678? There were a couple updates to the FastCGI stuff there which may have fixed this.

[jouvin@…]

I just retested with r3692. The problem is still there... First time after starting the fcgi (Apache restart). Retrying one minute later it works. The same for every potentially long operation (e.g. repository browsing in a branch with many child). The associated error in Apache log file is :

[Wed Sep 06 10:53:19 2006] [error] [client 134.158.88.66] FastCGI: comm with server "/htdocs/tractest/bin/trac.fcgi" aborted: idle timeout (30 sec)
[Wed Sep 06 10:53:19 2006] [error] [client 134.158.88.66] FastCGI: incomplete headers (0 bytes) received from server "/htdocs/tractest/bin/trac.fcgi"

I didn't find any way to increase the timeout.

[jouvin@…]

Previously, I missed that there was a traceback in the Apache main error log file. Here it is :

Unhandled exception in thread started by <bound method Connection.run of <trac.web._fcgi.Connection object at 0x1404c9d90>>
Traceback (most recent call last):
  File "/www/Web/servers/trac/0.10b1-3692/lib/python2.4/site-packages/trac/web/_fcgi.py", line 654, in run
    self.process_input()
  File "/www/Web/servers/trac/0.10b1-3692/lib/python2.4/site-packages/trac/web/_fcgi.py", line 690, in process_input
    self._do_params(rec)
  File "/www/Web/servers/trac/0.10b1-3692/lib/python2.4/site-packages/trac/web/_fcgi.py", line 789, in _do_params
    self._start_request(req)
  File "/www/Web/servers/trac/0.10b1-3692/lib/python2.4/site-packages/trac/web/_fcgi.py", line 773, in _start_request
    req.run()
  File "/www/Web/servers/trac/0.10b1-3692/lib/python2.4/site-packages/trac/web/_fcgi.py", line 582, in run
    self._flush()
  File "/www/Web/servers/trac/0.10b1-3692/lib/python2.4/site-packages/trac/web/_fcgi.py", line 589, in _flush
    self.stdout.close()
  File "/www/Web/servers/trac/0.10b1-3692/lib/python2.4/site-packages/trac/web/_fcgi.py", line 348, in close
    self._conn.writeRecord(rec)
  File "/www/Web/servers/trac/0.10b1-3692/lib/python2.4/site-packages/trac/web/_fcgi.py", line 705, in writeRecord
    rec.write(self._sock)
  File "/www/Web/servers/trac/0.10b1-3692/lib/python2.4/site-packages/trac/web/_fcgi.py", line 542, in write
    self._sendall(sock, header)
  File "/www/Web/servers/trac/0.10b1-3692/lib/python2.4/site-packages/trac/web/_fcgi.py", line 519, in _sendall
    sent = sock.send(data)
socket.error: (32, 'Broken pipe')

[mgood]

Replying to jouvin@lal.in2p3.fr:

Previously, I missed that there was a traceback in the Apache main error log file. Here it is :

...snip...

socket.error: (32, 'Broken pipe')

This just means that Apache killed the socket, so when Trac is trying to respond it can't. When this happens, there's nothing to be done on the Trac side.

You can set the timeout in the FastCgiConfig or FastCgiServer directives with the option -appConfigTimeout.

Try increasing the timeout to give the process some more time to start up.

[jouvin@…]

Thanks for the advice. In fact, the FastCgiServer? option is -idle-timeout instead of -appConfigTimeout (this one doesn't exist and -appConnTimeoutis not recommended).

I had to increase the timeout from 30s to 180s to have the project index working properly (120s was not enough). This looks surprising to me. The server running Trac is quite heavily loaded but still seems quite excessive.

I would say the main last changes are that quite a significant number of users started to use RSS reader... I have the impression this leads to Trac being being much less responsive... Does this make sense ?

BTW, what happens to other requests if trac.fcgi is busy during 3 minutes building the process index. Are other requests processed in parallel or are they waiting for the index to finish ?

Michel

[mgood]

Replying to jouvin@lal.in2p3.fr:

I had to increase the timeout from 30s to 180s to have the project index working properly (120s was not enough). This looks surprising to me. The server running Trac is quite heavily loaded but still seems quite excessive.

Yes, this does seem quite long. I'm running Trac on a shared host and have not had problems with the startup time. There may be a way to trace the Trac process to see if there's some operation in the startup that's hanging, but I don't have any good advice on how to do that.

I would say the main last changes are that quite a significant number of users started to use RSS reader... I have the impression this leads to Trac being being much less responsive... Does this make sense ?

"Good" RSS readers should default to only refreshing the feed once an hour. Unfortunately there are some that default to refreshing extremely frequently. So you may want to check the server log to see if there are some RSS readers overloading the site.

BTW, what happens to other requests if trac.fcgi is busy during 3 minutes building the process index. Are other requests processed in parallel or are they waiting for the index to finish ?

It shouldn't affect other requests.

[anonymous]

Replying to mgood:

Yes, this does seem quite long. I'm running Trac on a shared host and have not had problems with the startup time. There may be a way to trace the Trac process to see if there's some operation in the startup that's hanging, but I don't have any good advice on how to do that.

In fact we have 2 Trac "instances" running on the same host with separate project areas. One instance has around 25 projects, the other one 3. And the time to get the project index seems roughly proportional to the number of project (at least it is much quicker to get the index for the 3 projects instance).

I upgraded to the last version of sqlite and pysql but it didn't change anything.

[mgood]

I'm going to push back the milestone since I don't think this will be fixed for 0.10.

Replying to anonymous:

In fact we have 2 Trac "instances" running on the same host with separate project areas. One instance has around 25 projects, the other one 3. And the time to get the project index seems roughly proportional to the number of project (at least it is much quicker to get the index for the 3 projects instance).

Ok, that's helpful. Trac itself should be able to handle loading 25 projects fairly quickly. I just tested a directory here with 40 projects and it loaded within a few seconds. However, you may have a plugin that is slow doing the environment_needs_upgrade check. Can you provide a list of the plugins you have installed?

[anonymous]

I've also experienced this issue with just running "tracd", with Trac v 0.10

[wkornewald]

Just for the log: Related to #3957 and #3868

[cboos]

This might be related to the time needed for syncing the repository cache, see #4586.