Redmine

We have had a weird bug on our recently-upgraded Redmine server. It could be two bugs, but the symptoms seem so closely related that I feel they should be filed as one for now.

The problem is we can't download files twice from the "repository" tab reliably. For files larger than 64KB, they get truncated to 64KB the second time. Nothing really interesting shows up in the logs:

Started GET "/projects/civicrm-saas-traduction/repository/revisions/master/raw/l10n/fr_CA/civicrm.po" for X.X.X.X at 2015-03-30 17:10:14 -0400
Processing by RepositoriesController#raw as HTML
  Parameters: {"id"=>"civicrm-saas-traduction", "rev"=>"master", "path"=>"l10n/fr_CA/civicrm.po"}
  Current user: XXXXXXX (id=X)
  Rendered text template (0.0ms)
Sent data civicrm.po  (4.7ms)
Completed 200 OK in 807.8ms (Views: 4.5ms | ActiveRecord: 327.4ms)

Started GET "/projects/civicrm-saas-traduction/repository/revisions/master/raw/l10n/fr_CA/civicrm.po" for X,X,X,X at 2015-03-30 17:10:28 -0400
Processing by RepositoriesController#raw as */*
  Parameters: {"id"=>"civicrm-saas-traduction", "rev"=>"master", "path"=>"l10n/fr_CA/civicrm.po"}
  Current user: anonymous
  Rendered text template (0.0ms)
Sent data civicrm.po  (0.8ms)
Completed 200 OK in 33.1ms (Views: 0.7ms | ActiveRecord: 23.1ms)

The above is downloading the same "larger than 64KB" file twice. No error shows up in the production.log on the second try, but the file is truncated. Note that this works across user, and the phenomenon goes away after a while (say ~24h? need to be confirmed).

Now here's an example of a file smaller than 64KB:

Started GET "/projects/kt-sa-debian-upgrades/repository/revisions/master/entry/predict-os-2015-03-19.png" for 70.83.139.100 at 2015-03-30 17:10
:54 -0400
Processing by RepositoriesController#entry as HTML
  Parameters: {"id"=>"kt-sa-debian-upgrades", "rev"=>"master", "path"=>"predict-os-2015-03-19.png"}
  Current user: anarcat (id=3)
Creating scope :system. Overwriting existing method Enumeration.system.
Creating scope :sorted. Overwriting existing method User.sorted.
  Rendered text template (0.0ms)
Sent data predict-os-2015-03-19.png  (1.7ms)
Completed 200 OK in 592.4ms (Views: 1.4ms | ActiveRecord: 273.7ms)
Creating scope :sorted. Overwriting existing method Group.sorted.

Started GET "/projects/kt-sa-debian-upgrades/repository/revisions/master/entry/predict-os-2015-03-19.png" for 70.83.139.100 at 2015-03-30 17:11
:02 -0400
Processing by RepositoriesController#entry as */*
  Parameters: {"id"=>"kt-sa-debian-upgrades", "rev"=>"master", "path"=>"predict-os-2015-03-19.png"}
  Current user: anonymous
Completed 500 Internal Server Error in 35.9ms

ArgumentError (invalid byte sequence in UTF-8):
  lib/redmine/core_ext/string.rb:9:in `count'
  lib/redmine/core_ext/string.rb:9:in `is_binary_data?'
  app/controllers/repositories_controller.rb:199:in `is_entry_text_data?'
  app/controllers/repositories_controller.rb:175:in `entry_and_raw'
  app/controllers/repositories_controller.rb:161:in `entry'

The first attempt works, the second attempt completely fails with the above 500 error.

Environment:
  Redmine version                2.5.1.stable (2.5.1-2~bpo70+5 from Debian, upgraded from 1.4)
  Ruby version                   1.9.3-p194 (2012-04-20) [x86_64-linux]
  Rails version                  3.2.6
  Environment                    production
  Database adapter               MySQL (5.5.41-0+wheezy1)
SCM:
  Subversion                     1.6.17
  Mercurial                      2.2.2
  Cvs                            1.12.13
  Git                            1.9.1
  Filesystem
Redmine plugins:
  redmine_bootstrap_kit          0.2.0
  redmine_git_hosting            0.7.10
  redmine_openid_selector        0.0.1
  redmine_stealth                0.6.0