500 Internal Server Error when browsing a repository

Added by Anthony C about 7 years ago

I've added a subversion repository to one of our projects. When I go to the repository tab to browse the repository I get a 500 Internal Server Error. The production.log contains no entry at all for the page access. The strangest part is that another repository on another server works perfectly. Both the working and non-working servers run subversion-1.6.9-1 on CentOS 5. The biggest difference is that the non-working server is on a different subnet and required a firewall opening for port 443. Both servers return valid xml results when the svn commands are run by hand.

When I run redmine with "ruby script/server -e production -p 80" in screen I get disconnected from my SSH session and upon resuming find:

root@redmine:/usr/share/redmine# ruby script/server -e production -p 80
=> Booting WEBrick
=> Rails 2.3.5 application starting on http://0.0.0.0:80
=> Call with -d to detach
=> Ctrl-C to shutdown server
[2011-02-23 12:03:02] INFO WEBrick 1.3.1
[2011-02-23 12:03:02] INFO ruby 1.8.7 (2010-01-10) [x86_64-linux]
[2011-02-23 12:03:02] INFO WEBrick::HTTPServer#start: pid=5043 port=80
Killed

The Apache server log shows the generic error:
[Fri Feb 18 15:32:51 2011] [error] [client 10.xxx.xxx.xxx] Premature end of script headers: projects, referer: https://redmine.xxxxx.com/redmine/projects/xxxxx/settings

My environment:
root@redmine:/usr/share/redmine# RAILS_ENV=production ruby script/about
About your application's environment
Ruby version 1.8.7 (x86_64-linux)
RubyGems version 1.3.5
Rack version 1.0
Rails version 2.3.5
Active Record version 2.3.5
Active Resource version 2.3.5
Action Mailer version 2.3.5
Active Support version 2.3.5
Edge Rails revision unknown
Application root /usr/share/redmine-1.1.1
Environment production
Database adapter mysql
Database schema version 20101114115359

About your Redmine plugins
Redmine Hudson plugin 1.0.6.1

Replies (39)

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

Any suggestions for troubleshooting? Is there anything I can do to find a more meaningful error message?

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

I've discovered a new symptom. I was looking at /var/log/messages for another reason and noticed that Ruby had been invoking oom-killer.

I started up top and went to the page causing the error. At first svn and mysqld showed activity for a few seconds and then ruby went to 100% cpu and started consuming memory. It started at about 2% and didn't stop until it crashed at 85%+ of 4GB. The internal server error pops up at that point.

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

You could try to lower the number of revisions fetched at a time in app/models/repository/subversion.rb (line 49, actual value is 199 ?)

What's the result of the command svn log --xml -r 1:199 --verbose <repo_url> ?

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

The command:
sudo -u www-data svn --username xxxxx log -r 1:199 --verbose --config-dir /usr/share/redmine/svn --xml 'https://xxx.xxx.xxx.xxx/svn/xxxxx'@HEAD

Result:
Thousands (hundreds of thousands?) of lines of log downloading for 30 seconds or so.

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

Forgot to mention, it does display all of the log entries through 199 with no errors.

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

This may be the resulting Xml parsing which take such ressources.

Maybe you could try to install the libxml-ruby gem to make it faster ?

Or maybe it is not supposed to retrieve so much data, can't you attach us the very first part of it (anonymized) ?

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

Do you have a big amount of data committed in your firs 200 revs ?

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

I ran the command again and saved the output to a file. The file is 25MB and ~630k lines. Here's the first few lines:


<log>
<logentry
revision="1">
<author>root</author>
<date>2010-11-20T04:20:29.041788Z</date>
<paths>
<path
kind="file"
action="A">/trunk/external/xxxxx</path>
<path
kind="file"
action="A">/trunk/external/xxxxx</path>
<path
kind="file"
action="A">/trunk/libsrc/xxxxx</path>
<path
kind="file"
action="A">/trunk/libsrc/xxxxx</path>
<path
kind="file"
action="A">/trunk/libsrc/xxxxx</path>
<path
kind="file"
action="A">/trunk/libsrc/xxxxx</path>
<path
kind="file"
action="A">/trunk/external/xxxxx</path>
<path
kind="file"
action="A">/trunk/external/xxxxx</path>
<path
kind="file"
action="A">/trunk/external/xxxxx</path>

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

Same behavior after install libxml-ruby.

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

Result:
Thousands (hundreds of thousands?) of lines of log downloading for 30 seconds or so.

30 sec for 25 mb ?

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

It goes over a WAN connection, thus the slow speed. Still seems like a memory leak to me, parsing xml shouldn't chew up 4GB of memory.

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

Ok, but where is the memory leak ? Thought it could have been in the xml parsing part.

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

Could you post the full file once anonymized (compressed it should be small enough) ?

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

I'm not good enough with regular expressions to anonymize it... any other options?

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

You can try to replace line 149 of source:tags/1.1.1/lib/redmine/scm/adapters/subversion_adapter.rb#L149 with :

ActiveSupport::XmlMini.with_backend('LibXML').parse(output)

to truly make use of the libxml-ruby you installed before.

You could add some logger.info lines also.

I've attached such a modified subversion_adapter.rb.

This logs a lot in production.log, hope this will give us some info.

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

Progress! enabling the libxml parser solved the 500/memory leak/ruby crash. But the log reports exceptions thrown when browsing the repository (and other repositories). Also revision and comment information is missing from the interface. Log excerpt:

Fetching changesets for repository https://xxxx/svn/xxxx
Shelling out: svn --trust-server-cert --non-interactive --config-dir /usr/share/redmine/svn log --xml -r 200:1 --username xxxx --password xxxx --no-auth-cache --non-interactive --verbose 'https://xxxx/svn/xxxx/'
before XML parsing
exception thrown
end of fetching
Shelling out: svn --trust-server-cert --non-interactive --config-dir /usr/share/redmine/svn log --xml -r 245:201 --username xxxx --password xxxx --no-auth-cache --non-interactive --verbose 'https://xxxx/svn/xxxx/'
before XML parsing
exception thrown
end of fetching
Shelling out: svn --trust-server-cert --non-interactive --config-dir /usr/share/redmine/svn list --xml 'https://xxxx/svn/xxxx/'@HEAD --username xxxx --password xxxx --no-auth-cache --non-interactive
Found 5 entries in the repository for 'https://xxxx/svn/xxxx/'
Shelling out: svn --trust-server-cert --non-interactive --config-dir /usr/share/redmine/svn log --xml -r HEAD:1 --username xxxx --password xxxx --no-auth-cache --non-interactive --limit 10 'https://xxxx/svn/xxxx/'
before XML parsing
exception thrown
end of fetching

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

This does not look like progress to me, more like a bug in the subversion_adapter.rb I uploaded :(

Could you please try with this one ?

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

With new subversion_adapter.rb we're back to an internal server error with apache2 invoking oom-killer.

Log has:

Fetching changesets for repository https://xxxx/svn/xxxx
before svn command
Shelling out: svn --trust-server-cert --non-interactive --config-dir /usr/share/redmine/svn log --xml -r 200:1 --username xxxx --password xxxx --no-auth-cache --non-interactive --verbose 'https://xxxx/svn/xxxx/'
before XML parsing
reading revision 200
reading path /trunk/src/xxxx
reading path /trunk/src/xxxx
before paths array sorting
reading revision 199
reading path /trunk/src/xxxx
reading path /trunk/src/xxxx
before paths array sorting
reading revision 198

185k lines of paths and revisions later...

reading path /trunk/external/xxxx
reading path /trunk/external/xxxx
before paths array sorting
end of fetching
[[4;35;1mSQL (0.7ms)[[0m [[0mBEGIN[[0m
[[4;36;1mChangeset Columns (2.5ms)[[0m [[0;1mSHOW FIELDS FROM `changesets`[[0m
[[4;35;1mChangeset Load (1.7ms)[[0m [[0mSELECT `changesets`.id FROM `changesets` WHERE (`changesets`.`revision` = BINARY '1' AND `changesets`.repository_id = 12) LIMIT 1[[0m

and then 1k lines of SQL commands later the log ends

[[4;36;1mChange Create (0.3ms)[[0m   [[0;1mINSERT INTO `changes` (`changeset_id`, `action`, `branch`, `path`, `revision`, `from_path`, `from_revision`) VALUES(5317, 'A', NULL, '/trunk/external/xxxx', NULL, NULL, NULL)[[0m

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

Ok, so that would not be an adapter issue, more a repository one.

Could you try to do same without transaction ?

That is, replace subersion_adapter.rb back with original file, comment transaction do at source:/tags/1.1.1/app/models/repository/subversion.rb#L58 (and its matching end line) and try again keeping an eye on the memory usage over time.

You should maybe backup your db before starting :o

If this work, then this could be related to https://rails.lighthouseapp.com/projects/8994/tickets/6129-reduce-memory-bloat-in-activerecord-transactions.

RE: 500 Internal Server Error when browsing a repository - Added by Anthony C about 7 years ago

I commented out line 58 and 68, but ruby is still invoking oom-killer.

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

So, nothing to do with transactions :[

Try commenting them out and decrementing the step 199 to, e.g., 50 at line 55 :

identifier_to = [identifier_from + 199, scm_revision].min

to

identifier_to = [identifier_from + 50, scm_revision].min

RE: 500 Internal Server Error when browsing a repository - Added by Etienne Massip about 7 years ago

Does it crash when inserting the same record each time ?

1 2 (1-25/39)