When doing normal database queries with ActiveRecord I encounter following errors:
Mysql2::Error: Lost connection to MySQL server during query
or even
ActiveRecord::StatementInvalid (Mysql2::Error: MySQL client ran out of memory)
The errors are non-recoverable (reconnect is possible by app restart only) and aren't bound to specific database query (they pop up suddenly in various places of app).
The application is not high-loaded. Actually I am the only user of it.
Sometimes the application runs a whole night without any trouble, sometimes it crashes after several hours/minutes of operation. Sometimes WEBrick/Puma exit suddenly with some exit code without any MySQL errors before.
I tried to upgrade Rails from 4.0.4 to later version, tried to downgrade MySQL from 5.6 to 5.5, tried to change mysql2 gem version - nothing helped.
It couldn't be a network connectivity trouble because MySQL runs on the same machine and is accessed through localhost name.
The database doesn't store millions of rows and none of queries returns repeated rows.
I am not sure about initial connection because I honestly don't know whether Rails is reusing an existing connection for several queries or creating the new one for each query. It cannot be a long distance or slow connection because it is localhost.
Questions:
How did I manage to run into the situation?
What to do to resolve the problem?
Here is a piece of log:
Driver Load (0.0ms) SELECT `drivers`.* FROM `drivers` WHERE `drivers`.`ts_id` = 1
WorkShift Load (1.0ms) SELECT `work_shifts`.* FROM `work_shifts` WHERE `work_shifts`.`driver_id` = 1 AND `work_shifts`.`current_state` = 1 ORDER BY `work_shifts`.`scheduled_opened_at` DESC LIMIT 1
Trip Load (1.0ms) SELECT `trips`.* FROM `trips` WHERE `trips`.`work_shift_id` = 1 AND (current_state in (3,4,5,9)) ORDER BY `trips`.`id` ASC LIMIT 1
Mysql2::Error: Lost connection to MySQL server during query: SELECT `trips`.* FROM `trips` WHERE `trips`.`work_shift_id` = 1 AND (current_state in (3,4,5,9)) ORDER BY `trips`.`id` ASC LIMIT 1
2014-10-11 22:56:30 UpCloud(1).send_driver_statuses: Exception(ActiveRecord::StatementInvalid): Mysql2::Error: Lost connection to MySQL server during query: SELECT `trips`.* FROM `trips` WHERE `trips`.`work_shift_id` = 1 AND (current_state in (3,4,5,9)) ORDER BY `trips`.`id` ASC LIMIT 1
==== Stack trace: ====
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `query'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `block in execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_adapter.rb:442:in `block in log'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activesupport-4.0.4/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_adapter.rb:437:in `log'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:222:in `execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:226:in `exec_query'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:235:in `select'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract/database_statements.rb:32:in `select_all'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract/query_cache.rb:63:in `select_all'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/querying.rb:36:in `find_by_sql'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:585:in `exec_queries'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/association_relation.rb:15:in `exec_queries'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:471:in `load'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:220:in `to_a'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation/finder_methods.rb:326:in `find_first'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation/finder_methods.rb:91:in `first'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-deprecated_finders-1.0.3/lib/active_record/deprecated_finders/relation.rb:129:in `first'
D:/Work/disp/lib/ex/up_cloud.rb:365:in `up_driver_status'
D:/Work/disp/lib/ex/up_cloud.rb:416:in `block (4 levels) in send_driver_statuses'
C:in `each'
C:in `each'
D:/Work/disp/lib/ex/up_cloud.rb:415:in `block (3 levels) in send_driver_statuses'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:391:in `call'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:391:in `insert'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:375:in `method_missing'
D:/Work/disp/lib/ex/up_cloud.rb:414:in `block (2 levels) in send_driver_statuses'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:391:in `call'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:391:in `insert'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:375:in `method_missing'
D:/Work/disp/lib/ex/up_cloud.rb:413:in `block in send_driver_statuses'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:293:in `initialize'
D:/Work/disp/lib/ex/up_cloud.rb:412:in `new'
D:/Work/disp/lib/ex/up_cloud.rb:412:in `send_driver_statuses'
D:/Work/disp/lib/ex/up_cloud.rb:73:in `block in initialize'
Driver Load (1.0ms) SELECT drivers.id, work_shifts.latitude, work_shifts.longitude, work_shifts.updated_at FROM `drivers` INNER JOIN `work_shifts` ON `work_shifts`.`driver_id` = `drivers`.`id` WHERE `drivers`.`ts_id` = 1 AND `work_shifts`.`current_state` = 1
Mysql2::Error: MySQL client ran out of memory: SELECT `orders`.* FROM `orders` WHERE `orders`.`current_state` = 2
2014-10-11 22:56:32 Postman.postman thread: Exception(ActiveRecord::StatementInvalid): Mysql2::Error: MySQL client ran out of memory: SELECT `orders`.* FROM `orders` WHERE `orders`.`current_state` = 2
==== Stack trace: ====
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `query'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `block in execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_adapter.rb:442:in `block in log'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activesupport-4.0.4/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_adapter.rb:437:in `log'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:222:in `execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:226:in `exec_query'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:235:in `select'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract/database_statements.rb:32:in `select_all'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract/query_cache.rb:63:in `select_all'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/querying.rb:36:in `find_by_sql'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:585:in `exec_queries'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:471:in `load'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:220:in `to_a'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:565:in `blank?'
D:/Work/disp/lib/postman.rb:31:in `do_posting'
D:/Work/disp/lib/postman.rb:16:in `block (2 levels) in initialize'
D:/Work/disp/lib/advanced_logging.rb:8:in `with_level'
D:/Work/disp/lib/postman.rb:15:in `block in initialize'
The problem was executing database queries in different threads without proper threads synchronization.