500 Internal Server Error when browsing a repository

Added by Anthony C about 8 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 8 years ago

No, this time it crashed at:

[[4;35;1mChange Create (0.2ms)[[0m   [[0mINSERT INTO `changes` (`changeset_id`, `action`, `branch`, `path`, `revision`, `from_path`, `from_revision`) VALUES(5436, 'A', NULL, '/3rdparty/xxxx', NULL, NULL, NULL)[[0m
[[4;36;1mSQL (3.5ms)[[0m [[0;1mCOMMIT[[0m
before svn command
Shelling out: svn --trust-server-cert --config-dir /usr/share/redmine/svn log --xml -r 153:103 --username xxxx --password xxxx --no-auth-cache --non-interactive --verbose 'https://xxxx/svn/xxxx/'

Not important, but looks like 49 would be cleaner than 50.

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

Interesting! After I commented that out, I navigated to the repository page and after a minute or two received the usual 500 error. After checking out the logs I noticed that the first svn command had started at revisions 150-100 and then gone up to 200-150 as if 0-100 were done. So I refreshed the page and after a few seconds it loaded with all the info in place (revision, age, author, comments, file structure, diffs). The log shows that on the second page load it finished off the remaining revisions as I had suspected it would, 200 through the HEAD (275).

Maybe it's just a coincidence, but it looks like the last two times it crashed it occurred immediately after "shelling out" the svn command to start on the third range of revisions. Last time it crashed when starting 100-150 after doing 0-50 and 50-100. This time it crashed on 200-250 after doing 100-150 and 150-200.

[[4;35;1mSQL (3.0ms)[[0m   [[0mCOMMIT[[0m
before svn command
Shelling out: svn --trust-server-cert --config-dir /usr/share/redmine/svn log --xml -r 255:205 --username xxxx --password xxxx --no-auth-cache --non-interactive --verbose 'https://xxxx/svn/xxxx/'

Errno::ENOMEM (Cannot allocate memory - svn --trust-server-cert --config-dir /usr/share/redmine/svn log --xml -r 255:205 --username 'xxxx' --password 'xxxx' --no-auth-cache --non-interactive --verbose 'https://xxxx/svn/xxxx/'):
lib/redmine/scm/adapters/abstract_adapter.rb:191:in `popen'
lib/redmine/scm/adapters/abstract_adapter.rb:191:in `shellout'
lib/redmine/scm/adapters/abstract_adapter.rb:177:in `shellout'
lib/redmine/scm/adapters/subversion_adapter.rb:148:in `revisions'
app/models/repository/subversion.rb:56:in `fetch_changesets'
app/controllers/repositories_controller.rb:77:in `show'
/usr/lib/ruby/1.8/phusion_passenger/rack/request_handler.rb:95:in `process_request'
/usr/lib/ruby/1.8/phusion_passenger/abstract_request_handler.rb:207:in `main_loop'
/usr/lib/ruby/1.8/phusion_passenger/railz/application_spawner.rb:374:in `start_request_handler'
/usr/lib/ruby/1.8/phusion_passenger/railz/application_spawner.rb:332:in `handle_spawn_application'
/usr/lib/ruby/1.8/phusion_passenger/utils.rb:184:in `safe_fork'
/usr/lib/ruby/1.8/phusion_passenger/railz/application_spawner.rb:330:in `handle_spawn_application'
/usr/lib/ruby/1.8/phusion_passenger/abstract_server.rb:352:in `__send__'
/usr/lib/ruby/1.8/phusion_passenger/abstract_server.rb:352:in `main_loop'
/usr/lib/ruby/1.8/phusion_passenger/abstract_server.rb:196:in `start_synchronously'
/usr/lib/ruby/1.8/phusion_passenger/abstract_server.rb:163:in `start'
/usr/lib/ruby/1.8/phusion_passenger/railz/application_spawner.rb:209:in `start'
/usr/lib/ruby/1.8/phusion_passenger/spawn_manager.rb:262:in `spawn_rails_application'
/usr/lib/ruby/1.8/phusion_passenger/abstract_server_collection.rb:126:in `lookup_or_add'
/usr/lib/ruby/1.8/phusion_passenger/spawn_manager.rb:256:in `spawn_rails_application'
/usr/lib/ruby/1.8/phusion_passenger/abstract_server_collection.rb:80:in `synchronize'
/usr/lib/ruby/1.8/phusion_passenger/abstract_server_collection.rb:79:in `synchronize'
/usr/lib/ruby/1.8/phusion_passenger/spawn_manager.rb:255:in `spawn_rails_application'
/usr/lib/ruby/1.8/phusion_passenger/spawn_manager.rb:154:in `spawn_application'
/usr/lib/ruby/1.8/phusion_passenger/spawn_manager.rb:287:in `handle_spawn_application'
/usr/lib/ruby/1.8/phusion_passenger/abstract_server.rb:352:in `__send__'

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

I forgot to mention, it may be obvious but it seems like changing the increment from 199 to 49 was the "solution". I've uncommented after_create_part and it still works. Maybe the default increment should be lower? Or is it only beneficial in unusually large repositories like this one?

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

Anthony C wrote:

I noticed that the first svn command had started at revisions 150-100 and then gone up to 200-150 as if 0-100 were done.

Guess this could be due to the "no transaction" test you've done earlier ?

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

What's your Ruby 1.8.7 patch level ?

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

Etienne Massip wrote:

Guess this could be due to the "no transaction" test you've done earlier?

That was my thought too, and the logs agree.

Ruby info:

ii ruby 4.2
ii ruby1.8 1.8.7.249-2
ii ruby1.8-dev 1.8.7.249-2
ii rubygems 1.3.5-1ubuntu2
ii rubygems1.8 1.3.5-1ubuntu2

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

More info for you. I removed the repository to go through the process of adding it again. I noticed that unless I use the libxml backend I get a 500 error with nothing in the log.

Works:
ActiveSupport::XmlMini.backend = 'LibXML'
doc = ActiveSupport::XmlMini.parse(output)

Doesn't work:
#ActiveSupport::XmlMini.backend = 'LibXML'
doc = ActiveSupport::XmlMini.parse(output)

Also, this time Ruby crashed after the first 50 revisions and then after the next 150 and on the third attempt finished loading everything. So there's not a pattern of when it crashes.

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

In summary, it works only if the two next conditions are met :

  • Xml parsing lib is set to 'LibXml'
  • revisions step is lowered (49 / 50)

Then you don't have any error and the process run fully to its end.

Any other combination will cause a OOM SIGKILL.

Is that it ?

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

If those two conditions are met ruby still ends with an OOM SIGKILL the first two times Redmine tries to download and parse all the information, but after that the process completes successfully and the page functions normally.

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

Sorry, I'm not sure what you are asking.

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

Sorry, I meant : the transaction block was not commented (= transaction was used) ?

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

Correct, I didn't see a difference with it commented out.

1 2 (26-39/39)