长时间任务后，ActiveRecord 在简单更新期间抛出 Mysql2::Error::ConnectionError

Posted

技术标签:

【中文标题】长时间任务后，ActiveRecord 在简单更新期间抛出 Mysql2::Error::ConnectionError【英文标题】：ActiveRecord throws Mysql2::Error::ConnectionError during simple update after long task 【发布时间】：2021-10-30 02:09:57 【问题描述】：

我有一个简单的脚本，它负责在数据库中查找记录，进行一些长时间运行的计算，然后再次更新数据库。

这里是代码

DB_CONFIG = 
  adapter: 'mysql2',
  database: *******,
  username: *******,
  password: *******,
  host: *******,
  reconnect: true,
  read_timeout: 1800,
  write_timeout: 1800,
  connect_timeout: 1800
.freeze

DBRecord = ActiveRecord::Base
DBRecord.logger = Logger.new(STDOUT)
DBRecord.establish_connection(DB_CONFIG)

class ReocrJob < DBRecord
  self.table_name = 'reocr_job'
end

if __FILE__ == $PROGRAM_NAME
  begin
    reocr_job = ReocrJob.find(154)
    reocr_job.update(status: ReOCRStatus::PROCESSING)

    @logger.info "Slepping for a while"
    sleep(1000)
    @logger.info "Wake up! We have database to update!"

    reocr_job.update(status: ReOCRStatus::COMPLETED)
  rescue StandardError
    @logger.error "Update Failed"
    @logger.error $ERROR_INFO
    ReocrJob.find(154).update(status: ReOCRStatus::FAILED, comment: $ERROR_INFO.to_s)
  end
  @logger.info 'Done. '
end

第二个更新语句抛出错误（下面记录了 SQL 查询的完整输出）。

Mysql2::Error::ConnectionError: Lost connection to MySQL server during query (ActiveRecord::StatementInvalid)

这个错误被救援块捕获，令人惊讶的是，那里的更新语句工作正常！您可以在 SQL 调试日志中看到带有错误消息的更新语句工作正常。

这是完整的输出日志：

D, [2021-08-31T13:33:45.327712 #1039883] DEBUG -- :   ReocrJob Load (50.5ms)  SELECT `reocr_job`.* FROM `reocr_job` WHERE `reocr_job`.`id` = 154 LIMIT 1
D, [2021-08-31T13:33:45.414542 #1039883] DEBUG -- :   TRANSACTION (48.9ms)  BEGIN
D, [2021-08-31T13:33:45.465169 #1039883] DEBUG -- :   ReocrJob Update (50.3ms)  UPDATE `reocr_job` SET `reocr_job`.`status` = 'processing', `reocr_job`.`updated_at` = '2021-08-31 11:33:45' WHERE `reocr_job`.`id` = 154
D, [2021-08-31T13:33:45.572910 #1039883] DEBUG -- :   TRANSACTION (106.9ms)  COMMIT
I, [2021-08-31T13:33:45.573033 #1039883]  INFO -- : Slepping for a while
I, [2021-08-31T13:50:25.669822 #1039883]  INFO -- : Wake up! We have database to update!
D, [2021-08-31T13:50:25.723543 #1039883] DEBUG -- :   TRANSACTION (51.3ms)  BEGIN
E, [2021-08-31T13:50:25.724075 #1039883] ERROR -- : Update Failed
E, [2021-08-31T13:50:25.724176 #1039883] ERROR -- : Mysql2::Error::ConnectionError: Lost connection to MySQL server during query (ActiveRecord::StatementInvalid)
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/mysql2-0.5.3/lib/mysql2/client.rb:131:in `_query'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/mysql2-0.5.3/lib/mysql2/client.rb:131:in `block in query'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/mysql2-0.5.3/lib/mysql2/client.rb:130:in `handle_interrupt'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/mysql2-0.5.3/lib/mysql2/client.rb:130:in `query'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:206:in `block (2 levels) in execute'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:205:in `block in execute'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract_adapter.rb:696:in `block (2 levels) in log'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract_adapter.rb:695:in `block in log'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract_adapter.rb:687:in `log'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:204:in `execute'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/mysql/database_statements.rb:50:in `execute'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:219:in `begin_db_transaction'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/transaction.rb:207:in `materialize!'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/transaction.rb:285:in `block (2 levels) in materialize_transactions'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/transaction.rb:285:in `each'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/transaction.rb:285:in `block in materialize_transactions'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/transaction.rb:282:in `materialize_transactions'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/database_statements.rb:328:in `materialize_transactions'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:201:in `execute'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/mysql/database_statements.rb:50:in `execute'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:215:in `execute_and_free'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/mysql/database_statements.rb:76:in `block in exec_delete'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/mysql/database_statements.rb:75:in `exec_delete'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/database_statements.rb:179:in `update'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/query_cache.rb:22:in `update'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/persistence.rb:385:in `_update_record'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/persistence.rb:891:in `_update_row'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/locking/optimistic.rb:88:in `_update_row'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/persistence.rb:913:in `_update_record'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/attribute_methods/dirty.rb:195:in `_update_record'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/callbacks.rb:465:in `block in _update_record'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/callbacks.rb:824:in `_run_update_callbacks'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/callbacks.rb:465:in `_update_record'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/timestamp.rb:121:in `_update_record'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/persistence.rb:900:in `create_or_update'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/callbacks.rb:457:in `block in create_or_update'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/callbacks.rb:824:in `_run_save_callbacks'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/callbacks.rb:457:in `create_or_update'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/timestamp.rb:126:in `create_or_update'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/persistence.rb:474:in `save'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/validations.rb:47:in `save'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/transactions.rb:298:in `block in save'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/database_statements.rb:318:in `transaction'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/transactions.rb:298:in `save'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/suppressor.rb:44:in `save'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/persistence.rb:628:in `block in update'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `block in transaction'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `transaction'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
/home/klyda/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-6.1.4.1/lib/active_record/persistence.rb:626:in `update'
/home/klyda/findmypast/repos/press-freedom/images/reocr/database_breaker.rb:50:in `<main>'
D, [2021-08-31T13:50:26.078174 #1039883] DEBUG -- :   ReocrJob Load (352.6ms)  SELECT `reocr_job`.* FROM `reocr_job` WHERE `reocr_job`.`id` = 154 LIMIT 1
D, [2021-08-31T13:50:26.130003 #1039883] DEBUG -- :   TRANSACTION (49.4ms)  BEGIN
D, [2021-08-31T13:50:26.180344 #1039883] DEBUG -- :   ReocrJob Update (49.9ms)  UPDATE `reocr_job` SET `reocr_job`.`status` = 'failed', `reocr_job`.`updated_at` = '2021-08-31 11:50:26' WHERE `reocr_job`.`id` = 154
D, [2021-08-31T13:50:26.445102 #1039883] DEBUG -- :   TRANSACTION (264.0ms)  COMMIT
I, [2021-08-31T13:50:26.445227 #1039883]  INFO -- : Done. 

Process finished with exit code 0

这是我的 Ruby 版本和一些宝石：

➜ ruby --version   
ruby 3.0.1p64 (2021-04-05 revision 0fb782ee38) [x86_64-linux]


➜ gem list | grep 'activerecord\|mysql'
activerecord (6.1.4, 6.1.3.2, 5.2.6)
activerecord-import (1.2.0, 1.1.0)
mysql2 (0.5.3)

【问题讨论】：

【参考方案1】：

Mysql2::Error::ConnectionError 继承自 StandardError。这就是为什么您的 rescue StandardError 语句正在捕获它并执行下面的块。

Mysql2::Error::ConnectionError.ancestors
#=> [Mysql2::Error::ConnectionError, Mysql2::Error, StandardError, ...]

【讨论】：

是的，当然，我并不惊讶我的救援块正在捕获它，而不是该块内的 SQL 查询正在工作，而之前的那个正在抛出 Lost connection to MySQL server 。我可能会改写这句话更清楚;） 哦，我明白了，我的错。我猜您的连接仍然存在，因为您的 connect_timeout 大于您的 sleep 声明 - 但我无法给您详细的答案。也许您可以尝试设置降低超时以查看它的行为

以上是关于长时间任务后，ActiveRecord 在简单更新期间抛出 Mysql2::Error::ConnectionError的主要内容，如果未能解决你的问题，请参考以下文章

在后台运行长时间运行的并行任务，同时允许小型异步任务更新前台

向客户端发送有关视图中长时间运行任务的进度的更新

长时间运行的后台任务完成后应用程序未挂起

winform批量更新数据_长时间的执行会导致界面卡死

异步任务进度对话框需要很长时间才能完成 android 中的简单任务

iOS 在长时间运行任务后显示警报视图