trac 0.11.2.1 fails intermittently with malformed header from script. Bad header=3.09944152832e-06 10.0: trac.cgi

[davidthewatson@…]

I installed trac timing and estimation plugin 0.9.4 from the non-permissions branch into our trac 0.11.2.1 environment which was stable running on apache for years. As soon as I enable any of the T&E plugins, trac page requests begin failing intermittently with lines like this appearing in the apache error log:

malformed header from script. Bad header=3.09944152832e-06 10.0: trac.cgi

The "Bad header=*" value varies from line to line, but other than that it's the same. Sometime apache returns a 500, other times pages load partially with sub-elements failing (the home page will load without the logo, where the HTTP GET for the logo failed but the parent request did not. As soon as I disable the T&E plugins, this behavior stops.

It's not clear to me where this number in scientific notation is originating but it may be worth noting that I have the svn post commit hook installed and working. That is, I've been able to generate a ticket and file time against it using an SVN commit.

Any help is appreciated. I've instrumented the trac.cgi but that just got me the headers.

[Russ Tyndall]

Well that sounds perfectly horrible... I'm sorry you are having such issues. I don't think I have ever gotten a "bad header" message and I don't have any in my logs.

I assume you are hosting through trac.cgi based on the error message. We just moved from modpython to modfcgid and have not experienced anything like that in our years of running it. We have never tried running the trac.cgi however.

As trac.cgi is proclaimed to be vastly slower than any of the alternatives, is there any chance you would be willing to try installing modfcgid and the fcgi setup? If so, here is our conf, to make it easier for you.

ScriptAlias / /var/trac/trac.fcgi/

This is our FCGI script at /var/trac/trac.fcgi

#!/usr/bin/env python
import os

from trac.web.main import dispatch_request
try:
    from flup.server.fcgi import WSGIServer
except ImportError:
    from trac.web._fcgi import WSGIServer

if __name__ == '__main__':
    os.environ['TRAC_ENV_PARENT_DIR'] = '/var/trac'
    os.environ['PYTHON_EGG_CACHE'] = '/var/trac-eggs'
    WSGIServer(dispatch_request).run()

Also, what version of Apache are you running?

[davidthewatson@…]

That's right about trac.cgi. Thanks for documenting the fcgi setup, I've been saying we should be going that route for a while now as that's how I've run other trac sites previously. I inherited a legacy setup here. Just haven't gotten around to it.

Perhaps ironically, we had mod_python installed but weren't using it and when we removed it yesterday, our memory usage went from 6GB to ~1 GB. This is centos 5/Apache 2.2.3.

It turns out that there was more than one problem hiding in our plugin config. First was that the billing page was failing with a key error generated by the sqlquerymacro plugin that hadn't implemented the get htdocs call since it had no static content itself. Why this showed up in billing, I have no idea but the only way I could get the message to actually render was to realize that the linkify js wasn't loading and all the billing links were wrong as a result. When I requested the linkify js directly, trac would then paint the key error on htdocs for the sqlquerymacro plugin. I fixed the bug in the sqlquerymacro plugin and billing started working.

The malformed header problems seem to go away as a result of disabling TimeTrackingSetupParticipant. I'm not sure what's going on there but I saw this suggested on another unrelated forum posting on a google search. We're using sqllite and I did all the setup steps as described in the wiki. Our trac seems stable now, so as long as we can run without the aforementioned TimeTrackingSetupParticipant, we're good to go.

Thanks again.

[Russ Tyndall]

Replying to davidthewatson@gmail.com:

The malformed header problems seem to go away as a result of disabling TimeTrackingSetupParticipant. I'm not sure what's going on there but I saw this suggested on another unrelated forum posting on a google search. We're using sqllite and I did all the setup steps as described in the wiki. Our trac seems stable now, so as long as we can run without the aforementioned TimeTrackingSetupParticipant, we're good to go.

Thanks again.

Once the plugin is installed you shouldn't need the TimeTrackingSetupParticipant enabled except when you are trying to upgrade to a new version (when it could be enabled for the upgrade and then disabled again). Interestingly, the TimeTrackingSetupParticipant does not interact with the request in any way (meaning it is not directly manipulating the headers collection, and so shouldnt be causing problems). That said its possible that it is incorrectly detecting that it needs an update and this is triggering an associated bug in the trac core.

If you are interested in tracking this down further, the next step would be to enable TracLogging and see what trac is doing when it is throwing those errors. That said, if you are happy with just disabling that component and your trac runs fine, I am also ok with just calling this good. If you want to do more, just reopen.

Thanks for your error report,

Russ