Intermittent 500 Internal Server Errors

Added by Uttam Sapkota 2 months ago

Some users are getting 500 errors when logging in and when trying to browse certain pages or when the server's been idle for a while or visiting my controller page.

The production logs where 500 error occurred are the followings:

Completed 500 Internal Server Error in 1ms (ActiveRecord: 0.3ms)

ActiveRecord::StatementInvalid (Mysql2::Error: MySQL server has gone away: SELECT MAX(`settings`.`updated_on`) FROM `settings`):
  app/models/setting.rb:231:in `check_cache'
  app/controllers/application_controller.rb:90:in `user_setup'

Started GET "/" for 127.0.0.1 at 2019-12-29 08:52:50 +0000
Processing by MyController#page as HTML
Completed 500 Internal Server Error in 1ms (ActiveRecord: 0.2ms)

ActiveRecord::StatementInvalid (Mysql2::Error: MySQL server has gone away: SELECT MAX(`settings`.`updated_on`) FROM `settings`):
  app/models/setting.rb:231:in `check_cache'
  app/controllers/application_controller.rb:90:in `user_setup'

Started GET "/" for 127.0.0.1 at 2019-12-29 08:52:56 +0000

Mysql2::Error (Can't connect to MySQL server on 'rds-prod-db-xxxxx.c3uzu7me4rud.us-east-1.rds.amazonaws.com' (111)):

Completed 500 Internal Server Error in 82ms (ActiveRecord: 39.0ms)

ActionView::Template::Error (No route matches {:action=>"index", :controller=>"welcome", :format=>"atom", :project_id=>"makalu"}):
    4:   xml.link    "rel" => "self", "href" => url_for(:params => request.query_parameters, :only_path => false, :format => 'atom')
    5:   xml.link    "rel" => "alternate", "href" => url_for(:params => request.query_parameters.merge(:format => nil, :key => nil), :only_path => false)
    6:   xml.id      home_url
    7:   xml.icon    favicon_url
    8:   xml.updated((@items.first ? @items.first.event_datetime : Time.now).xmlschema)
    9:   xml.author  { xml.name "#{Setting.app_title}" }
   10:   xml.generator(:uri => Redmine::Info.url) { xml.text! Redmine::Info.app_name; }
  app/helpers/application_helper.rb:1471:in `favicon_url'
  app/views/common/feed.atom.builder:7:in `block in _app_views_common_feed_atom_builder___4486188461752896589_70048120855000'
  app/views/common/feed.atom.builder:2:in `_app_views_common_feed_atom_builder___4486188461752896589_70048120855000'
  app/controllers/application_controller.rb:529:in `render_feed'
  app/controllers/issues_controller.rb:62:in `block (2 levels) in index'
  app/controllers/issues_controller.rb:46:in `index'
  lib/redmine/sudo_mode.rb:63:in `sudo_mode'


Completed 500 Internal Server Error in 134ms (ActiveRecord: 69.2ms)

ActiveRecord::StatementInvalid (Mysql2::Error: Deadlock found when trying to get lock; try restarting transaction: UPDATE `issues` SET `issues`.`done_ratio` = 90, `issues`.`updated_on` = '2020-01-20 08:22:21', `issues`.`lock_version` = 49 WHERE `issues`.`id` = 328453 AND `issues`.`lock_version` = 48):
  app/models/issue.rb:210:in `create_or_update'
  app/models/issue.rb:1716:in `recalculate_attributes_for'
  app/models/issue.rb:1666:in `update_parent_attributes'
  app/models/issue.rb:210:in `create_or_update'
  app/controllers/issues_controller.rb:558:in `block in save_issue_with_child_records'
  app/controllers/issues_controller.rb:546:in `save_issue_with_child_records'
  app/controllers/issues_controller.rb:168:in `update'
  lib/redmine/sudo_mode.rb:63:in `sudo_mode'

Completed 500 Internal Server Error in 1ms (ActiveRecord: 0.2ms)

ActiveRecord::StatementInvalid (Mysql2::Error: MySQL server has gone away: UPDATE `tokens` SET `tokens`.`updated_on` = '2020-02-02 09:07:22' WHERE `tokens`.`user_id` = 289 AND `tokens`.`value` = 'a30e44e2ac37c8ba31eb383a409509c0d5fbb8be' AND `tokens`.`action` = 'session' AND (created_on > '2020-02-01 09:07:22') AND (updated_on > '2020-02-01 09:07:22')):
  app/models/user.rb:445:in `verify_session_token'
  app/controllers/application_controller.rb:77:in `session_expired?'
  app/controllers/application_controller.rb:67:in `session_expiration'

Started GET "/" for 127.0.0.1 at 2020-02-02 09:07:25 +0000

I saw an earlier topic having almost the same problem but have not found the solution yet.
Information:

Environment:
  Redmine version                3.4.4.stable
  Ruby version                   2.2.2-p95 (2015-04-13) [x86_64-linux]
  Rails version                  4.2.8
  Environment                    production
  Database adapter               Mysql2
SCM:
  Subversion                     1.7.14
  Git                            1.8.3.1
  Filesystem                     
Redmine plugins:
  redmine_query_share            2.1.0
  redmine_agile                  1.4.5
  sidebar_hide                   0.0.7

Ruby Server: Puma,
Puma_worker_killer config:

PumaWorkerKiller.config do |config|
    config.ram           = 4096 # mb
    config.frequency     = 60   # seconds
    config.percent_usage = 0.90
    config.rolling_restart_frequency = 10 * 3600 # 12 hours in seconds, or 12.hours if using Rails
    config.reaper_status_logs = true # setting this to false will not log lines like:
    # PumaWorkerKiller: Consuming 54.34765625 mb with master and 2 workers.

    config.pre_term = -> (worker) { puts "Worker #{worker.inspect} being killed" }
  end

ANY HELP??
Thanks.