Sidekiq でのリトライエラー

RBoy · 2022 年 4 月 19 日午前 7:25

2.9.0beta4 への最近のアップグレード後にこのエラーを見るのは初めてです。

Jobs::UserEmail

{“type”=>“user_watching_first_post”, “user_id”=>1735, “notification_id”=>33246, “notification_data_hash”=>{“topic_title”=>“Some new notes”, “original_post_id”=>11592, “original_post_type”=>1, “original_username”=>“xfactor”, “revision_number”=>nil, “display_username”=>“xfactor”}, “notification_type”=>“watching_first_post”, “post_id”=>11592, “current_site_id”=>“default”}

Jobs::HandledExceptionWrapper: Wrapped ActiveRecord::RecordInvalid: Validation failed: Post has already been taken

再試行しようとしても、また失敗します。これはユーザーによって作成された新しいトピックに関するもののようです。

これはどういう意味で、どうすれば修正できますか？

RBoy · 2022 年 4 月 19 日午後 4:41

サーバーがこの新しいトピックについて、そのカテゴリをウォッチしていた全員に多くのメールを正常に送信したことがわかります。メールログやメールサーバーにもエラーは表示されていません。

では、これは何を示しているのでしょうか？

md-misko · 2022 年 4 月 22 日午前 4:55

ここでもこの種のエラーは初めて発生しました。再試行しても解決しません。他のすべてのメールは配信されています。

Jobs::UserEmail

{"type"=>"user_private_message", "user_id"=>1513, "notification_id"=>871360, "notification_data_hash"=>{"topic_title"=>"Topic title", "original_post_id"=>220174, "original_post_type"=>1, "original_username"=>"username", "revision_number"=>nil, "display_username"=>"user", "group_name"=>nil}, "notification_type"=>"private_message", "post_id"=>220174, "current_site_id"=>"default"}

Jobs::HandledExceptionWrapper: Wrapped ActiveRecord::RecordInvalid: Validation failed: Post has already been taken

バックトレース

/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/validations.rb:80:in `raise_validation_error'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/validations.rb:53:in `save!'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/transactions.rb:302:in `block in save!'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/connection_adapters/abstract/database_statements.rb:318:in `transaction'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/transactions.rb:302:in `save!'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/suppressor.rb:48:in `save!'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/persistence.rb:55:in `create!'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/relation.rb:799:in `_create!'

RBoy · 2022 年 4 月 22 日午後 1:35

ディスコースのログも確認しました。

メッセージ（21件報告あり）

ジョブ例外：検証に失敗しました：投稿は既に取得されています

バックトレース

/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/validations.rb:80:in `raise_validation_error'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/validations.rb:53:in `save!'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/transactions.rb:302:in `block in save!'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/connection_adapters/abstract/database_statements.rb:318:in `transaction'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/transactions.rb:302:in `save!'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/suppressor.rb:48:in `save!'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/persistence.rb:55:in `create!'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.4.7/lib/active_record/relation.rb:799:in `_create!'

RBoy · 2022 年 4 月 26 日午後 7:08

これをサポートではなくバグに移動します

JammyDodger · 2022 年 5 月 3 日午前 10:59

こんにちは @RBoy

このエラーはまだ発生していますか？

RBoy · 2022 年 5 月 3 日午後 2:05

そのエントリについては、昨日までリトライループに陥ったままでした。数百回のリトライの後、ついに我慢できなくなり削除しました。何か壊してしまったのではないかと心配です。

再び見ることはありませんでしたが、その後、1つの投稿で数百件のメールをトリガーするようなイベントは発生していません。しかし、これがどこから来て、何を意味するのかを理解できると良いのですが。

mcdanlj · 2022 年 5 月 22 日午後 5:07

数日前、3つのメッセージでこのエラーが発生しました。クリティカルではなかったため、リトライが成功しなかったのでジョブを削除しました。

現在2001件あり、テストアカウントは本来受け取るはずの週刊ダイジェストを受け取っていません。

現在、8695449cfc を実行中です。

mcdanlj · 2022 年 5 月 23 日午前 12:15

bf987af3ca にアップグレードし、すべてを再試行しましたが、sidekiq コンソールに Jobs::HandledExceptionWrapper: Wrapped ActiveRecord::RecordInvalid: Validation failed: Post has already been taken が少なくとも 38 件表示されます。

mcdanlj · 2022 年 5 月 24 日午後 12:35

さらにアップデートがないため、現在は30件まで減っています。タイムアウトしているのだろうと推測していますが、テストアカウントには（遅延していましたが）週刊ダイジェストが届いたので、これに関連していると思われます。実際に諦めているものがあるかどうかを知るために、ログのどこを見ればよいか分かりません。

ほとんど失敗しているように見えますが、時々成功することもあり、これはどこかで競合状態が発生していることを示唆しています。

私のバックトレースは、@RBoyと@md-miskoが見たものと同じですが、ここに「コピー」ボタンから取得した切り捨てられたものではなく、完全なバックトレースを示します。

activerecord-7.0.3/lib/active_record/validations.rb:80:in `raise_validation_error'
activerecord-7.0.3/lib/active_record/validations.rb:53:in `save!'
activerecord-7.0.3/lib/active_record/transactions.rb:302:in `block in save!'
activerecord-7.0.3/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
activerecord-7.0.3/lib/active_record/connection_adapters/abstract/database_statements.rb:314:in `transaction'
activerecord-7.0.3/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
activerecord-7.0.3/lib/active_record/transactions.rb:302:in `save!'
activerecord-7.0.3/lib/active_record/suppressor.rb:54:in `save!'
activerecord-7.0.3/lib/active_record/persistence.rb:55:in `create!'
activerecord-7.0.3/lib/active_record/relation.rb:869:in `_create!'
activerecord-7.0.3/lib/active_record/relation.rb:115:in `block in create!'
activerecord-7.0.3/lib/active_record/relation.rb:880:in `_scoping'
activerecord-7.0.3/lib/active_record/relation.rb:428:in `scoping'
activerecord-7.0.3/lib/active_record/relation.rb:115:in `create!'
activerecord-7.0.3/lib/active_record/relation.rb:219:in `block in create_or_find_by!'
activerecord-7.0.3/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
activesupport-7.0.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
activesupport-7.0.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
activesupport-7.0.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
activesupport-7.0.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
activerecord-7.0.3/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
activerecord-7.0.3/lib/active_record/connection_adapters/abstract/database_statements.rb:316:in `transaction'
activerecord-7.0.3/lib/active_record/transactions.rb:209:in `transaction'
activerecord-7.0.3/lib/active_record/relation.rb:67:in `block in transaction'
activerecord-7.0.3/lib/active_record/relation.rb:880:in `_scoping'
activerecord-7.0.3/lib/active_record/relation.rb:428:in `scoping'
activerecord-7.0.3/lib/active_record/relation.rb:67:in `transaction'
activerecord-7.0.3/lib/active_record/relation.rb:219:in `create_or_find_by!'
activerecord-7.0.3/lib/active_record/querying.rb:22:in `create_or_find_by!'
/var/www/discourse/lib/email/sender.rb:498:in `get_reply_key'
/var/www/discourse/lib/email/sender.rb:105:in `send'
/var/www/discourse/app/jobs/regular/user_email.rb:83:in `send_user_email'
/var/www/discourse/app/jobs/regular/user_email.rb:38:in `execute'
/var/www/discourse/app/jobs/base.rb:232:in `block (2 levels) in perform'
/var/www/discourse/lib/rails_multisite/connection_management.rb:80:in `with_connection'
/var/www/discourse/app/jobs/base.rb:221:in `block in perform'
/var/www/discourse/app/jobs/base.rb:217:in `each'
/var/www/discourse/app/jobs/base.rb:217:in `perform'
sidekiq-6.4.2/lib/sidekiq/processor.rb:196:in `execute_job'
sidekiq-6.4.2/lib/sidekiq/processor.rb:164:in `block (2 levels) in process'
sidekiq-6.4.2/lib/sidekiq/middleware/chain.rb:138:in `block in invoke'
/var/www/discourse/lib/sidekiq/pausable.rb:138:in `call'
sidekiq-6.4.2/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
sidekiq-6.4.2/lib/sidekiq/middleware/chain.rb:143:in `invoke'
sidekiq-6.4.2/lib/sidekiq/processor.rb:163:in `block in process'
sidekiq-6.4.2/lib/sidekiq/processor.rb:136:in `block (6 levels) in dispatch'
sidekiq-6.4.2/lib/sidekiq/job_retry.rb:114:in `local'
sidekiq-6.4.2/lib/sidekiq/processor.rb:135:in `block (5 levels) in dispatch'
sidekiq-6.4.2/lib/sidekiq.rb:40:in `block in <module:Sidekiq>'
sidekiq-6.4.2/lib/sidekiq/processor.rb:131:in `block (4 levels) in dispatch'
sidekiq-6.4.2/lib/sidekiq/processor.rb:257:in `stats'
sidekiq-6.4.2/lib/sidekiq/processor.rb:126:in `block (3 levels) in dispatch'
sidekiq-6.4.2/lib/sidekiq/job_logger.rb:13:in `call'
sidekiq-6.4.2/lib/sidekiq/processor.rb:125:in `block (2 levels) in dispatch'
sidekiq-6.4.2/lib/sidekiq/job_retry.rb:81:in `global'
sidekiq-6.4.2/lib/sidekiq/processor.rb:124:in `block in dispatch'
sidekiq-6.4.2/lib/sidekiq/job_logger.rb:39:in `prepare'
sidekiq-6.4.2/lib/sidekiq/processor.rb:123:in `dispatch'
sidekiq-6.4.2/lib/sidekiq/processor.rb:162:in `process'
sidekiq-6.4.2/lib/sidekiq/processor.rb:78:in `process_one'
sidekiq-6.4.2/lib/sidekiq/processor.rb:68:in `run'
sidekiq-6.4.2/lib/sidekiq/util.rb:56:in `watchdog'
sidekiq-6.4.2/lib/sidekiq/util.rb:65:in `block in safe_thread'

これをデバッグするために、他に提供できる情報はありますか？

RGJ · 2022 年 5 月 25 日午前 6:19

3件の投稿が既存のトピックにマージされました: Email Hostname Certificate Mismatch Causing sidekiq Queue Overload, Severe Site Instability

sok777 · 2022 年 5 月 26 日午前 6:53

私もこの問題が発生しています！

mcdanlj · 2022 年 5 月 26 日午後 3:01

メールサーバーがラウンドロビンで別のサーバーの証明書を使用していたことを発見し、ホスト名の不一致が問題であると期待していました。証明書の不一致がないサーバーに変更する過程で、b850c12793 に更新しましたが、問題は解決しませんでした。いくつかのジョブを再試行しましたが、どれも正常に完了しませんでした。したがって、このバグは隠れた証明書の不一致の症状ではありません。

これは discourse_docker 2a9faf7e5680b9 でビルドされました。

discourse_docker を 241a42ce718 に更新し、それに伴って discourse を 95e7e10417 に更新しても、問題は解決しませんでした。まだ 30 件の失敗が再試行されています。

RBoy · 2022 年 5 月 26 日午後 6:50

説明されている内容とこの投稿を見ると、複数の問題がある可能性があります。

サーバーがメールの再試行をスロットルしておらず、タイムアウトまたはメールサーバーによって拒否されている可能性があります。しかし、証明書と構成が有効であってもメールが送信されない場合は、他の根本的な問題があります。一部ではディスク容量を消費しているようにも見えます。私は自分のものをチェックしましたが、ここでは気づきませんでした。

mcdanlj · 2022 年 5 月 26 日午後 7:15

スペース不足ではなく、レースコンディションではないように見えるように、再実行するジョブを1つだけ選択した場合でも発生します。明らかに複数の問題があり、ここで見ていることは、リンクされたトピックとは関係ありません。

（結局、証明書の問題ではありませんでした。サーバー名は代替サーバー名にありました。しかし、SNに一致するホスト名を使用するように変更しましたが、違いはありませんでした。）

大量のメールを正常に送信していますが、これらのジョブがいくつかスタックしているだけです。たとえば、診断に役立つログエントリが何であるかわかりません。

blake · 2022 年 6 月 3 日午後 10:41

現時点では、この問題を再現する失敗するテストを追加するプルリクエストのドラフトを作成しました。

github.com/discourse/discourse

FIX: Email Send post has already been taken error

main ← email-send-post-taken-error

opened 10:39PM - 03 Jun 22 UTC

oblakeerickson

+9 -1

Adding a failing test first before coming up with a good solution. Related: 357…011eb3b4e9c5fb860a34ecbb2f5cb89e89a7a The above commit changed ``` PostReplyKey.find_or_create_by_safe! ``` to ``` PostReplyKey.create_or_find_by! ``` But I don't think it is working as a 1-1 replacement because of the `Validation failed: Post has already been taken` error we are receiving with this change. Also we need to make sure we don't re-introduce any concurrency issues. Reported: https://meta.discourse.org/t/224706/13

問題の原因となっているコードの行がわかったので、すぐに良い解決策を見つけられることを願っています。

mcdanlj · 2022 年 6 月 7 日午後 12:21

29件の失敗したメールを確認し、送信すべき重要なものがないことを確認しました。私の知る限り、何もありませんでしたので、メールジョブがアップグレードにまたがることによる一時的な問題の可能性があるため、sidekiq内のすべてのジョブを削除しました。しかし、さらなる更新を適用せずに、同じ失敗の別の単一のケースが発生しました。

これは継続的な問題であり、一時的なものではないという情報として共有します。

blake · 2022 年 6 月 7 日午後 2:30

上記のコード修正はマージされました。お時間のある時に最新の変更を git pull し、コンテナを再構築していただけますでしょうか？

mcdanlj · 2022 年 6 月 7 日午後 11:14

ジョブのアップグレードと再試行により、メールの送信に成功しました。メールログを確認したところ、送信されたと報告されていました。

ありがとうございます！

トピック		返信	表示
Severe Email Issue since last update a couple days ago - 3.4.0.beta4-dev Support	25	359	2025 年 2 月 16 日
Email jobs failing due to smtpserverbusy Installation email	9	1918	2019 年 11 月 27 日
When Jobs::UserEmail fail the email that failed is not logged Support	6	1988	2022 年 11 月 9 日
Sidekiq got error when sending mail after upgrade to latest version Support sidekiq	2	77	2025 年 3 月 4 日
Lots of retries mail in sidekiq after upgrade discourse to 3.5.0.beta8-dev( 4893bda14a ) Support	1	35	2025 年 7 月 9 日

Sidekiq でのリトライエラー

関連トピック