Redmine

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

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.

bump

bump2

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> ?

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.

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

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) ?

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

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>

Same behavior after install libxml-ruby.

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

30 sec for 25 mb ?

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.

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

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

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

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)

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.

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

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 ?

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

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.

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

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

No difference =(

Does it crash when inserting the same record each time ?