Intermittent 500 internal errors
Added by Rik Gy over 10 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 10 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 10 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 10 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 10 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 10 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 10 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 10 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