Intermittent 500 internal errors

Added by Rik Gy over 6 years ago

I've just set up a fresh install of:

OS: Ubuntu 14.04 LTS
HTTP Server: Apache/Passenger (Apache - 2.4.7)
Ruby version: ruby 2.0.0p481 (2014-05-08 revision 45883) [x86_64-linux]
Rails version: Rails 3.2.19
mysql  Ver 14.14 Distrib 5.5.38, for debian-linux-gnu (x86_64) using readline 6.3
redmine db encoding: utf8

Server locale:
> username@hostname~$ locale
> LANG=en_US.UTF-8
> LANGUAGE=en_US:en
> LC_CTYPE="en_US.UTF-8" 
> LC_NUMERIC="en_US.UTF-8" 
> LC_TIME="en_US.UTF-8" 
> LC_COLLATE="en_US.UTF-8" 
> LC_MONETARY="en_US.UTF-8" 
> LC_MESSAGES="en_US.UTF-8" 
> LC_PAPER="en_US.UTF-8" 
> LC_NAME="en_US.UTF-8" 
> LC_ADDRESS="en_US.UTF-8" 
> LC_TELEPHONE="en_US.UTF-8" 
> LC_MEASUREMENT="en_US.UTF-8" 
> LC_IDENTIFICATION="en_US.UTF-8" 
> LC_ALL=

The DB is migrated from an earlier 2.4.2 install.

I've noticed some of my user's are getting intermittent 500 errors when logging in (or if they're logged in through cookie, when trying to browse certain pages), in the morning or when the server's been idle for a while.
I've noticed the production.log also spitting out the wrong timezone in one case from the same browser (checked that user's timezone, if that helps)?
We're in the /Europe/Stockholm timezone, second 500-error in the log below says Dublin?

Checking my production.log it tells me this:

Started GET "/users/36" for [MASKED IP] at 2014-08-19 08:10:51 +0200
Processing by UsersController#show as HTML
  Parameters: {"id"=>"36"}
  Current user: [MASKED LDAP USERNAME] (id=36)
  Rendered users/show.html.erb within layouts/base (22.1ms)
Completed 500 Internal Server Error in 114.7ms

ActionView::Template::Error (cannot load such file -- tzinfo/definitions/Europe/Stockholm):
    45:
    46: <div id="activity">
    47: <% @events_by_day.keys.sort.reverse.each do |day| %>
    48: <h4><%= format_activity_day(day) %></h4>
    49: <dl>
    50: <% @events_by_day[day].sort {|x,y| y.event_datetime <=> x.event_datetime }.each do |e| -%>
    51:   <dt class="<%= e.event_type %>">
  app/models/user.rb:437:in `today'
  app/helpers/application_helper.rb:231:in `format_activity_day'
  app/views/users/show.html.erb:48:in `block in _app_views_users_show_html_erb__531584968933002312_63249760'
  app/views/users/show.html.erb:47:in `each'
  app/views/users/show.html.erb:47:in `_app_views_users_show_html_erb__531584968933002312_63249760'
  app/controllers/users_controller.rb:76:in `block (2 levels) in show'
  app/controllers/users_controller.rb:75:in `show'

[...omitted log output...]

Started GET "/my/account" for [MASKED IP, the same as above] at 2014-08-19 08:10:58 +0200
Processing by MyController#account as HTML
  Current user: [MASKED LDAP USERNAME, same as above] (id=36)
  Rendered users/_mail_notifications.html.erb (17.9ms)
  Rendered users/_preferences.html.erb (5.2ms)
  Rendered my/account.html.erb within layouts/base (33.5ms)
Completed 500 Internal Server Error in 43.2ms

ActionView::Template::Error (cannot load such file -- tzinfo/definitions/Europe/Dublin):
    1: <%= labelled_fields_for :pref, @user.pref do |pref_fields| %>
    2: <p><%= pref_fields.check_box :hide_mail %></p>
    3: <p><%= pref_fields.time_zone_select :time_zone, nil, :include_blank => true %></p>
    4: <p><%= pref_fields.select :comments_sorting, [[l(:label_chronological_order), 'asc'], [l(:label_reverse_chronological_order), 'desc']] %></p>
    5: <p><%= pref_fields.check_box :warn_on_leaving_unsaved %></p>
    6: <% end %>
  lib/redmine/views/labelled_form_builder.rb:42:in `time_zone_select'
  app/views/users/_preferences.html.erb:3:in `block in _app_views_users__preferences_html_erb__4280354043280162759_69854225159020'
  app/helpers/application_helper.rb:1050:in `labelled_fields_for'
  app/views/users/_preferences.html.erb:1:in `_app_views_users__preferences_html_erb__4280354043280162759_69854225159020'
  app/views/my/account.html.erb:43:in `block in _app_views_my_account_html_erb___4541838569531402333_63105120'
  app/helpers/application_helper.rb:1043:in `labelled_form_for'
  app/views/my/account.html.erb:9:in `_app_views_my_account_html_erb___4541838569531402333_63105120'

I saw an earlier topic having almost the same problem, but he considered it solved after reviewing his filepermissions.
About that time i got log output as described in the field below this paragraph.
I've reviewed the filepermissions/ownership (www-data:www-data, 775) on the server, and it looks like it's fixed the problem below.

Link to previous topic: http://www.redmine.org/boards/2/topics/43627

Started GET "/my/page" for [MASKED IP, the same as above] at 2014-08-18 12:58:05 +0200
Processing by MyController#page as HTML
  Current user: [MASKED LDAP USERNAME] (id=3)
  Rendered news/_news.html.erb (0.0ms)
  Rendered my/blocks/_news.html.erb (10.4ms)
  Rendered my/blocks/_timelog.html.erb (5.5ms)
  Rendered issues/_list_simple.html.erb (19.0ms)
  Rendered my/blocks/_issuesassignedtome.html.erb (44.5ms)
  Rendered issues/_list_simple.html.erb (14.7ms)
  Rendered my/blocks/_issueswatched.html.erb (27.8ms)
  Rendered my/page.html.erb within layouts/base (90.3ms)
Completed 500 Internal Server Error in 97.4ms

ActionView::Template::Error (cannot load such file -- active_support/multibyte/unicode):
    17:       <td class="project"><%= link_to_project(issue.project) %></td>
    18:       <td class="tracker"><%= issue.tracker %></td>
    19:       <td class="subject">
    20:         <%= link_to(issue.subject.truncate(60), issue_path(issue)) %> (<%= issue.status %>)
    21:       </td>
    22:     </tr>
    23:     <% end %>
  app/views/issues/_list_simple.html.erb:20:in `block (2 levels) in _app_views_issues__list_simple_html_erb__1225784539915115850_55538840'
  app/views/issues/_list_simple.html.erb:11:in `each'
  app/views/issues/_list_simple.html.erb:11:in `block in _app_views_issues__list_simple_html_erb__1225784539915115850_55538840'
  app/views/issues/_list_simple.html.erb:2:in `_app_views_issues__list_simple_html_erb__1225784539915115850_55538840'
  app/views/my/blocks/_issueswatched.html.erb:8:in `_app_views_my_blocks__issueswatched_html_erb___4220156679842397938_70106790870080'
  app/views/my/page.html.erb:20:in `block in _app_views_my_page_html_erb___3817531552599329398_56507780'
  app/views/my/page.html.erb:17:in `each'
  app/views/my/page.html.erb:17:in `_app_views_my_page_html_erb___3817531552599329398_56507780'

I just barely have time to login to the server to review the production.log, before they're reporting that it's working again.
I first thought it was a cookie/cache thing on the client side, since sometimes changing their browser is working. But that could perhaps be because of the time delay of when their next request are going out to the server?

Replies (8)

RE: Intermittent 500 internal errors - Added by Jan Niggemann (redmine.org team member) over 6 years ago

in the morning or when the server's been idle for a while.

Hmmm... Do you have any of PassengerMaxPoolSize, PassengerMaxPreloaderIdleTime or PoolIdleTime set?
And what about PassengerMinInstances and PassengerPreStart?

RE: Intermittent 500 internal errors - Added by Rik Gy over 6 years ago

PassengerMaxPoolSize 20
PassengerMaxPreloaderIdleTime 0
PassengerPoolIdleTime 1000
PassengerMinInstances 6
PassengerPreStart https://localhost

I haven't touched the PassengerPreStart URL. I'll have a look at changing that to the site's URL/ServerName.

RE: Intermittent 500 internal errors - Added by Jan Niggemann (redmine.org team member) over 6 years ago

When this happens again, please check the status of passenger (passenger-status) and post the output.

Does everybody check redmine in the morning, leading to a DOS-like scenario? How many users do you serve?
Depending on your environment, you might set PassengerPoolIdleTime to zero and increase the MinInstances...

RE: Intermittent 500 internal errors - Added by Rik Gy over 6 years ago

The site's a real small one (expect around 30 users all at once within the next year).
The errors were reported when about 2-3 people were trying to use it at once, so I don't think it's bc of a DOS-like burden on the machine.

I've set the PassengerPreStart and PassengerPoolIdleTime to 0 now, did not recieve any other notifications from my users today.
If I get another round of 500 error's, I'll get back to this topic.

Otherwise, consider this solved.

Thanks for your help Jan!

RE: Intermittent 500 internal errors - Added by Rik Gy over 6 years ago

I guess I was too quick to answer this.

Just happened again, granted i didn't get to the passenger-status until about 7mins later.

[username]@[hostname]:[folder]# passenger-status
Version : 4.0.48
Date    : 2014-08-20 15:28:34 +0200
Instance: 6436
----------- General information -----------
Max pool size : 20
Processes     : 10
Requests in top-level queue : 0

----------- Application groups -----------
[folder]#default:
  App root: /[folder]
  Requests in queue: 0
  * PID: 6692    Sessions: 0       Processed: 1       Uptime: 2h 27m 50s
    CPU: 0%      Memory  : 35M     Last used: 2h 27m 5
  * PID: 6699    Sessions: 0       Processed: 1       Uptime: 2h 27m 50s
    CPU: 0%      Memory  : 32M     Last used: 2h 27m 5
  * PID: 6706    Sessions: 0       Processed: 97      Uptime: 2h 27m 50s
    CPU: 0%      Memory  : 69M     Last used: 23s ago
  * PID: 6713    Sessions: 0       Processed: 0       Uptime: 2h 27m 50s
    CPU: 0%      Memory  : 8M      Last used: 2h 27m 5
  * PID: 6720    Sessions: 0       Processed: 0       Uptime: 2h 27m 50s
    CPU: 0%      Memory  : 8M      Last used: 2h 27m 5
  * PID: 6727    Sessions: 0       Processed: 0       Uptime: 2h 27m 50s
    CPU: 0%      Memory  : 8M      Last used: 2h 27m 5
  * PID: 6734    Sessions: 0       Processed: 0       Uptime: 2h 27m 50s
    CPU: 0%      Memory  : 8M      Last used: 2h 27m 5
  * PID: 6741    Sessions: 0       Processed: 0       Uptime: 2h 27m 49s
    CPU: 0%      Memory  : 8M      Last used: 2h 27m 4
  * PID: 6748    Sessions: 0       Processed: 0       Uptime: 2h 27m 49s
    CPU: 0%      Memory  : 8M      Last used: 2h 27m 4
  * PID: 6755    Sessions: 0       Processed: 0       Uptime: 2h 27m 49s
    CPU: 0%      Memory  : 3M      Last used: 2h 27m 4
Started GET "/" for [ip] at 2014-08-20 15:21:37 +0200
Processing by WelcomeController#index as HTML
  Current user: [username] (id=5)
  Rendered welcome/index.html.erb within layouts/base (9.1ms)
Completed 500 Internal Server Error in 141.3ms

ActionView::Template::Error (cannot load such file -- tzinfo/definitions/Europe/Stockholm):
    20:     <% for project in @projects %>
    21:       <% @project = project %>
    22:       <li>
    23:       <%= link_to_project project %> (<%= format_time(project.created_on) %>)
    24:       <%= textilizable project.short_description, :project => project %>
    25:       </li>
    26:     <% end %>
  lib/redmine/i18n.rb:60:in `format_date'
  lib/redmine/i18n.rb:71:in `format_time'
  app/views/welcome/index.html.erb:23:in `block in _app_views_welcome_index_html_erb___1267430472203800314_58679640'
  app/views/welcome/index.html.erb:20:in `each'
  app/views/welcome/index.html.erb:20:in `_app_views_welcome_index_html_erb___1267430472203800314_58679640'
PassengerMinInstances 10
PassengerMaxPoolSize 20
PassengerPoolIdleTime 0

RE: Intermittent 500 internal errors - Added by Jan Niggemann (redmine.org team member) over 6 years ago

So it probably was PID 6706 as all others were idle >2h...

 PID: 6706    Sessions: 0       Processed: 97      Uptime: 2h 27m 50s
    CPU: 0%      Memory  : 69M     Last used: 23s ago

Anyway, what's more interesting is

ActionView::Template::Error (cannot load such file -- tzinfo/definitions/Europe/Stockholm)

Do you have any plugins installed, and do any of those need the tzinfo gem? Is the tzinfo gem installed?
Please check if you have weird PassengerRoot oder PassengerRuby settings and if your ruby gems directory has proper permissions.

RE: Intermittent 500 internal errors - Added by Rik Gy over 6 years ago

Jan Niggemann (redmine.org team member) wrote:

So it probably was PID 6706 as all others were idle >2h...
[...]

Anyway, what's more interesting is

ActionView::Template::Error (cannot load such file -- tzinfo/definitions/Europe/Stockholm)

Do you have any plugins installed, and do any of those need the tzinfo gem? Is the tzinfo gem installed?
Please check if you have weird PassengerRoot oder PassengerRuby settings and if your ruby gems directory has proper permissions.

There's a plugin installed, but it should only trigger on issue updates (integration against zendesk).
The page's work later on, so I don't see how that's affecting things?

I just realized that i checked encryption of the admin accounts home folder, where my RVM-installation is located.
The 500 error-message seems to disappear once i login to that account.
Will perform a move of rvm to a different folder later today and tell you if that fixes it.

Found this method on stack overflow about moving the RVM-folder:
http://stackoverflow.com/a/15302680

RE: Intermittent 500 internal errors - Added by Rik Gy over 6 years ago

This solved our issue.

(1-8/8)