Defect #7699

Subversion: 500 Internal Server Error when browsing a repository

Added by Anthony C over 6 years ago. Updated almost 4 years ago.

Status:ReopenedStart date:2011-02-23
Priority:NormalDue date:
Assignee:-% Done:

0%

Category:SCM
Target version:-
Resolution: Affected version:1.1.1

Description

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 good information when the svn commands are run by hand (I've included these at the bottom).

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

Masked out results of manual svn list commands:

Non-working svn output:
setit@redmine:~$ sudo -u www-data svn --username redminesvn list --config-dir /usr/share/redmine/svn --xml 'https://149.8.205.147/svn/zop'@HEAD

<lists>
<list
path="https://XXXXX/XXXXX">
<entry
kind="dir">
<name>XXXXX</name>
<commit
revision="165">
<author>XXXXX</author>
<date>2011-02-17T22:14:31.210436Z</date>
</commit>
</entry>
<entry
kind="dir">
<name>RPMS</name>
<commit
revision="166">
<author>XXXXX</author>
<date>2011-02-17T22:15:39.495387Z</date>
</commit>
</entry>
<entry
kind="dir">
<name>branches</name>
<commit
revision="151">
<author>XXXXX</author>
<date>2011-02-17T15:25:01.243637Z</date>
</commit>
</entry>
<entry
kind="dir">
<name>tags</name>
<commit
revision="147">
<author>XXXXX</author>
<date>2011-02-15T19:18:56.290041Z</date>
</commit>
</entry>
<entry
kind="dir">
<name>trunk</name>
<commit
revision="174">
<author>XXXXX</author>
<date>2011-02-18T20:53:01.961666Z</date>
</commit>
</entry>
</list>
</lists>

Working svn output:
setit@redmine:~$ sudo -u www-data svn --username redminesvn list --config-dir /usr/share/redmine/svn --xml 'https://subversion.setcorp.com/set_it'@HEAD

<lists>
<list
path="https://XXXXX/XXXXX">
<entry
kind="dir">
<name>branches</name>
<commit
revision="1">
<author>XXXXX</author>
<date>2008-11-26T02:24:32.556798Z</date>
</commit>
</entry>
<entry
kind="dir">
<name>tags</name>
<commit
revision="1">
<author>XXXXX</author>
<date>2008-11-26T02:24:32.556798Z</date>
</commit>
</entry>
<entry
kind="dir">
<name>trunk</name>
<commit
revision="55">
<author>XXXXX</author>
<date>2011-01-19T21:33:32.032020Z</date>
</commit>
</entry>
</list>
</lists>


Related issues

Related to Redmine - Defect #633: Redmine crashes randomly Closed 2008-02-12
Related to Redmine - Patch #7528: Fetch small initial set of repository changesets New 2011-02-03
Duplicated by Redmine - Defect #9337: Out of memory when browsing subversion repository with la... Closed 2011-09-28

History

#1 Updated by Toshi MARUYAMA over 6 years ago

  • Category set to SCM

#2 Updated by Anthony C over 6 years ago

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

#3 Updated by Anthony C over 6 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.

#4 Updated by Anthony C over 6 years ago

bump, still experiencing this problem

#5 Updated by Etienne Massip over 6 years ago

No exception stack if you run WEBrick in debug mode (-B switch, if I remember well) ?

#6 Updated by Anthony C over 6 years ago

Are you sure it's -B?

root@redmine:/usr/share/redmine# ruby script/server -B
server: invalid option: -B

I found another symptom. If I try to update the repos offline, I get the same behavior (ruby using 100% CPU and consuming memory until oom-killer steps in):

root@redmine:/usr/share/redmine# ruby script/runner "Repository.fetch_changesets" -e production
Killed

#7 Updated by Etienne Massip over 6 years ago

Was -B for mongrel, my mistake.

You can change logging level in config/environments/production.rb :

config.log_level = :debug

#8 Updated by Anthony C over 6 years ago

Even with debug logging enabled nothing gets logged when I try to access the repository page, the process just gets killed in the same way I've described.

#9 Updated by Etienne Massip over 6 years ago

Do you get a core dump ?

#10 Updated by Anthony C over 6 years ago

I don't see one in std streams or the redmine production or development log or in syslog or messages. Would it be somewhere else? Would the call trace be helpful? It doesn't look that helpful...

#11 Updated by Etienne Massip over 6 years ago

To get the stack trace.

#12 Updated by Anthony C over 6 years ago

Mar 8 12:23:50 redmine kernel: [12104.250221] ruby invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0
Mar 8 12:23:50 redmine kernel: [12104.250235] ruby cpuset=/ mems_allowed=0
Mar 8 12:23:50 redmine kernel: [12104.250245] Pid: 2168, comm: ruby Not tainted 2.6.32-24-server #39-Ubuntu
Mar 8 12:23:50 redmine kernel: [12104.250248] Call Trace:
Mar 8 12:23:51 redmine kernel: [12104.250296] [<ffffffff810b363d>] ? cpuset_print_task_mems_allowed+0x9d/0xb0
Mar 8 12:23:51 redmine kernel: [12104.250312] [<ffffffff810f6e64>] oom_kill_process+0xd4/0x2f0
Mar 8 12:23:51 redmine kernel: [12104.250317] [<ffffffff810f7420>] ? select_bad_process+0xd0/0x110
Mar 8 12:23:51 redmine kernel: [12104.250321] [<ffffffff810f74b8>] __out_of_memory+0x58/0xc0
Mar 8 12:23:51 redmine kernel: [12104.250325] [<ffffffff810f764e>] out_of_memory+0x12e/0x1a0
Mar 8 12:23:51 redmine kernel: [12104.250348] [<ffffffff8155aa3e>] ? _spin_lock+0xe/0x20
Mar 8 12:23:51 redmine kernel: [12104.250353] [<ffffffff810fa6d1>] __alloc_pages_slowpath+0x511/0x580
Mar 8 12:23:51 redmine kernel: [12104.250358] [<ffffffff810fa8b1>] __alloc_pages_nodemask+0x171/0x180
Mar 8 12:23:51 redmine kernel: [12104.250371] [<ffffffff8112d6c7>] alloc_pages_current+0x87/0xd0
Mar 8 12:23:51 redmine kernel: [12104.250376] [<ffffffff810f4637>] __page_cache_alloc+0x67/0x70
Mar 8 12:23:51 redmine kernel: [12104.250385] [<ffffffff810fe209>] __do_page_cache_readahead+0xc9/0x210
Mar 8 12:23:51 redmine kernel: [12104.250390] [<ffffffff810fe371>] ra_submit+0x21/0x30
Mar 8 12:23:51 redmine kernel: [12104.250393] [<ffffffff810f5efe>] filemap_fault+0x3fe/0x450
Mar 8 12:23:51 redmine kernel: [12104.250399] [<ffffffff811126c4>] __do_fault+0x54/0x500
Mar 8 12:23:51 redmine kernel: [12104.250403] [<ffffffff81115c08>] handle_mm_fault+0x1a8/0x3c0
Mar 8 12:23:51 redmine kernel: [12104.250407] [<ffffffff81117e55>] ? remove_vma+0x65/0x80
Mar 8 12:23:51 redmine kernel: [12104.250412] [<ffffffff8155d5b5>] do_page_fault+0x125/0x3b0
Mar 8 12:23:51 redmine kernel: [12104.250416] [<ffffffff8155af05>] page_fault+0x25/0x30
Mar 8 12:23:51 redmine kernel: [12104.250419] Mem-Info:
Mar 8 12:23:51 redmine kernel: [12104.250422] Node 0 DMA per-cpu:
Mar 8 12:23:51 redmine kernel: [12104.250425] CPU 0: hi: 0, btch: 1 usd: 0
Mar 8 12:23:51 redmine kernel: [12104.250427] Node 0 DMA32 per-cpu:
Mar 8 12:23:51 redmine kernel: [12104.250431] CPU 0: hi: 186, btch: 31 usd: 178
Mar 8 12:23:51 redmine kernel: [12104.250437] active_anon:220136 inactive_anon:22536 isolated_anon:0
Mar 8 12:23:51 redmine kernel: [12104.250438] active_file:64 inactive_file:38 isolated_file:0
Mar 8 12:23:51 redmine kernel: [12104.250439] unevictable:0 dirty:0 writeback:0 unstable:0
Mar 8 12:23:51 redmine kernel: [12104.250440] free:2000 slab_reclaimable:689 slab_unreclaimable:2015
Mar 8 12:23:51 redmine kernel: [12104.250442] mapped:112 shmem:11373 pagetables:1795 bounce:0
Mar 8 12:23:51 redmine kernel: [12104.250444] Node 0 DMA free:4036kB min:60kB low:72kB high:88kB active_anon:11576kB inactive_anon:256kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15312kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:4kB kernel_stack:0kB pagetables:24kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:64 all_unreclaimable? yes
Mar 8 12:23:51 redmine kernel: [12104.250457] lowmem_reserve[]: 0 994 994 994
Mar 8 12:23:51 redmine kernel: [12104.250462] Node 0 DMA32 free:3964kB min:4000kB low:5000kB high:6000kB active_anon:868968kB inactive_anon:89888kB active_file:256kB inactive_file:152kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1018016kB mlocked:0kB dirty:0kB writeback:0kB mapped:448kB shmem:45492kB slab_reclaimable:2756kB slab_unreclaimable:8056kB kernel_stack:840kB pagetables:7156kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:617 all_unreclaimable? yes
Mar 8 12:23:51 redmine kernel: [12104.250475] lowmem_reserve[]: 0 0 0 0
Mar 8 12:23:51 redmine kernel: [12104.250480] Node 0 DMA: 1*4kB 2*8kB 3*16kB 2*32kB 3*64kB 1*128kB 2*256kB 0*512kB 1*1024kB 1*2048kB 0*4096kB = 4036kB
Mar 8 12:23:51 redmine kernel: [12104.250497] Node 0 DMA32: 21*4kB 1*8kB 0*16kB 1*32kB 0*64kB 0*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 3964kB
Mar 8 12:23:51 redmine kernel: [12104.250513] 11487 total pagecache pages
Mar 8 12:23:51 redmine kernel: [12104.250515] 0 pages in swap cache
Mar 8 12:23:51 redmine kernel: [12104.250522] Swap cache stats: add 0, delete 0, find 0/0
Mar 8 12:23:51 redmine kernel: [12104.250524] Free swap = 0kB
Mar 8 12:23:51 redmine kernel: [12104.250526] Total swap = 0kB
Mar 8 12:23:51 redmine kernel: [12104.257967] 262128 pages RAM
Mar 8 12:23:51 redmine kernel: [12104.257972] 6292 pages reserved
Mar 8 12:23:51 redmine kernel: [12104.257974] 16969 pages shared
Mar 8 12:23:51 redmine kernel: [12104.257976] 247176 pages non-shared
Mar 8 12:23:51 redmine kernel: [12104.257981] Out of memory: kill process 2168 (ruby) score 109350 or a child
Mar 8 12:23:51 redmine kernel: [12104.380239] Killed process 2168 (ruby)

#13 Updated by Anthony C over 6 years ago

Is there any other information I can find or provide? Thanks for the assistance.

#14 Updated by Toshi MARUYAMA over 6 years ago

  • Subject changed from 500 Internal Server Error when browsing a repository to Subversion: 500 Internal Server Error when browsing a repository

#15 Updated by Anthony C over 6 years ago

  • Status changed from New to Resolved

Resolved by changing /app/models/repository/subversion.rb, line 55 from:

identifier_to = [identifier_from + 199, scm_revision].min

to:

identifier_to = [identifier_from + 49, scm_revision].min

See: http://www.redmine.org/boards/2/topics/22059?r=22854

#16 Updated by Etienne Massip over 6 years ago

It's a workaround but I'd like to find the source of this issue, as this looks to be the same as #633 which is still open.

Somehow related to http://redmine.ruby-lang.org/issues/4293 ?

#17 Updated by Jeremy Brown over 6 years ago

redmine is reliably eating all of system memory when accessing a svn repo with fetch_changeset. Specifically, it fails on any of several changes which include 10,000+ files (e.g. checking in big third-party source trees.) There's something specifically about the size of the changeset which seems to be making it fail.

Dialing the identifier increment down didn't help at all --- small changesets don't bother it, but the giant ones choke it dead.

Ubuntu versions:
sqlite3 3.6.22
ruby 1.8.7.302
rails 2.3.11
redmine 1.2.0
svn 1.6.6

Here's an example run at the command line, with a little debugging info added:
Fetching changes from 8133
Fetching changes from 8134
Fetching changes from 8135 <------ this is the giant one --- about 34,000 files added. It completes, but then...
Fetching changes from 8136
/usr/share/redmine/vendor/rails/railties/lib/commands/runner.rb:48: /usr/share/redmine/lib/redmine/scm/adapters/abstract_adapter.rb:213:in `popen': Cannot allocate memory - 'svn' log --xml -r 8136:8136 --username 'jhbrown' --password ELIDEDFORBUG --no-auth-cache --non-interactive --verbose 'svn://localhost:3691//' (Errno::ENOMEM)
from /usr/share/redmine/lib/redmine/scm/adapters/abstract_adapter.rb:213:in `shellout'
from /usr/share/redmine/lib/redmine/scm/adapters/abstract_adapter.rb:194:in `shellout'
from /usr/share/redmine/lib/redmine/scm/adapters/subversion_adapter.rb:170:in `revisions'
from /usr/share/redmine/app/models/repository/subversion.rb:67:in `fetch_changesets'
from /usr/lib/ruby/1.8/active_record/associations/association_proxy.rb:215:in `send'
from /usr/lib/ruby/1.8/active_record/associations/association_proxy.rb:215:in `method_missing'
from /usr/share/redmine/app/models/repository.rb:243:in `fetch_changesets'
from /usr/share/redmine/app/models/repository.rb:240:in `each'
from /usr/share/redmine/app/models/repository.rb:240:in `fetch_changesets'
from (eval):1
from /usr/lib/ruby/1.8/rubygems/custom_require.rb:31:in `eval'
from /usr/share/redmine/vendor/rails/railties/lib/commands/runner.rb:48
from /usr/lib/ruby/1.8/rubygems/custom_require.rb:31:in `gem_original_require'
from /usr/lib/ruby/1.8/rubygems/custom_require.rb:31:in `require'
from script/runner:3

#18 Updated by Jan Niggemann (redmine.org team member) almost 5 years ago

Closing this, status is resolved since 400 days and more (issue was last updated more than 400 days ago)...

#19 Updated by Jan Niggemann (redmine.org team member) almost 5 years ago

  • Status changed from Resolved to Closed

#20 Updated by Adam Clark over 4 years ago

I am seeing this issue right now in 1.3.1 -- this doesn't seem fixed to me.

#21 Updated by Filou Centrinov over 4 years ago

The current Redmine version is 2.3. Please upgrade your Redmine.

#22 Updated by Toshi MARUYAMA over 4 years ago

  • Status changed from Closed to Reopened

#23 Updated by Adam Clark over 4 years ago

Upgrading to 2.3 didn't solve the problem.

Not sure if this should go into a new ticket, but in our case it looks like the root problem is the diff functionality -- for a very large changeset, SubversionAdapter::diff reads the entire diff into memory (we have some that are hundreds of megabytes), which chews up an enormous amount of memory that doesn't seem to get returned to the system. (Ruby may GC it internally, but external programs like svn and sendmail fail.)

For the standard diffs based on UnifiedDiff (inline and side-by-side) this content gets truncated after a set number of lines, so I tried using that value in SubversionAdapter::diff to limit the number of lines read from svn, and the problem disappeared.

          # Load more than the max so that an overflow is detected
          max_lines = Setting.diff_max_lines_displayed.to_i + 10
          shellout(cmd) do |io|
            io.each_line do |line|
              diff << line
              return diff if diff.length > max_lines
            end
          end

The only problem with this is that there's also a "unified" diff, which returns the full, raw diff. I think this is just the svn command output, so in theory it could be just piped back to the user without reading the whole thing into memory, but it seems like that would require the base Adapter::diff API to change so that it returns something other than an array.

#24 Updated by Dave Lowndes about 4 years ago

Not sure if exactly the same issue but I also get Ruby/Redmine using up all my memory when trying to view a large repository for the first time. After a while it gets killed and I get a 500 Apache error:

Jul 26 13:12:42 redmine kernel: [6139889.588711] apache2 invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0
...
Jul 26 13:12:42 redmine kernel: [6139889.591117] Out of memory: Kill process 330 (ruby) score 805 or sacrifice child
Jul 26 13:12:42 redmine kernel: [6139889.591133] Killed process 330 (ruby) total-vm:1650732kB, anon-rss:586792kB, file-rss:0kB

I can't find any entry in Redmine's production.log with debug level enabled.

I have a smaller repository on the same server with the exact same settings except for the address (both access via file:///) and it's working fine.

#26 Updated by Dave Lowndes almost 4 years ago

Reposting my post from the link above here.

This out of memory problem completely blocks the use of the repository feature for us so it's a major disturbance.

I have two svn repositories sitting in the same location on the same server as Redmine. Both are configured identically with the file:// location in Redmine. One repository works fine, but the other shows a 500 error after a minute when trying to browse. I'm assuming this is because it has a much larger revision count (4600 vs 500). I've tried refreshing multiple times hoping that this would eventually load the data but it's not working. I've run rails runner "Repository.fetch_changesets" -e production every hour overnight and it doesn't help.

How do I find out what's happening and deal with this? I've seen older posts about editing the changesets volume grabbed each time (or something) but the subversion adapter has changed since then.

This is Redmine 2.3.1.

This is what I get in the apache log:

[Mon May 20 10:33:55 2013] [error] [client xxx.xx.xx.xxx] Premature end of script headers: projects, referer: http://redmine.ourdomain.com/projects/myproject/repository
[ pid=16991 file=ext/apache2/Hooks.cpp:684 time=2013-05-20 10:33:56.204 ]:
The backend application (process 17936) did not send a valid HTTP response; instead, it sent nothing at all. It is possible that it has crashed; please check whether there are crashing bugs in this application.

I try to run ./script/rails runner "Repository.fetch_changesets" -e production and the process just gets Killed after some time:

Oct 23 09:03:16 redmine kernel: [7015239.446418] Out of memory: Kill process 15756 (ruby) score 641 or sacrifice child
Oct 23 09:03:16 redmine kernel: [7015239.446431] Killed process 15756 (ruby) total-vm:1400980kB, anon-rss:369264kB, file-rss:0kB

Also available in: Atom PDF