Sidekiq 재시도 오류

기여 버그
1

최근 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

재시도를 시도하면 다시 실패합니다. 이는 사용자가 만든 새로운 주제에 대한 것으로 보입니다.

이것의 의미는 무엇이며 어떻게 수정해야 하나요?

2개의 좋아요
Disabling starttls or certificate verification does not work any more
2

이 새로운 주제에 대해 해당 카테고리를 지켜보고 있는 모든 사람에게 이메일이 정상적으로 발송된 것을 확인했습니다. 이메일 로그나 이메일 서버에서도 오류가 보이지 않습니다.

그렇다면 이 메시지는 무엇을 의미하는 것일까요?

3

여기서 같은 유형의 첫 번째 오류가 발생했으며, 재시도해도 해결되지 않습니다. 다른 모든 이메일은 정상적으로 전달되었습니다:

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!'
4

저도 방금 디스코urs 로그를 확인했습니다:

Message (21 copies reported)

Job exception: Validation failed: Post has already been taken


Backtrace

/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!'
5

이 이슈를 지원 대신 버그로 이동합니다

1개의 좋아요
6

안녕하세요 @RBoy :slight_smile:

여전히 이 오류가 발생하나요?

7

해당 항목에 대해서는, 수백 번의 재시도 끝에 결국 지쳐서 삭제한 어제까지도 재시도 루프에 갇혀 있었습니다. 무언가를 망치지 않았기를 바랍니다.

다시 확인해 본 적은 없지만, 단일 게시물에서 수백 통의 이메일을 유발하는 이벤트가 발생하지도 않았거든요. 하지만 이것이 어디서 비롯된 것이며 어떤 의미를 갖는지 이해할 수 있다면 좋겠습니다.

8

몇日前, 세 개의 메시지에서 이 오류를 확인했습니다. 중요한 오류가 아니었기 때문에 재시도가 성공하지 못하자 해당 작업들을 삭제했습니다.

현재 작업이 2001개나 쌓여 있고, 매주 받아야 할 주간 다이제스트를 테스트 계정으로 받지 못했습니다.

image
image1248×285 43 KB

현재 8695449cfc를 실행 중입니다.

2개의 좋아요
9

bf987af3ca로 업그레이드하고 모든 것을 다시 시도해 보았지만, 여전히 sidekiq 콘솔에 Jobs::HandledExceptionWrapper: Wrapped ActiveRecord::RecordInvalid: Validation failed: Post has already been taken가 최소 38개 이상 표시되고 있습니다.

2개의 좋아요
13

추가 업데이트가 없으므로, 현재 30개까지 줄었습니다. 제 추측으로는 타임아웃이 발생하고 있는 것 같지만, 제 테스트 계정에는 (지연된) 주간 다이제스트가 도착했고, 이것이 관련이 있을 것으로 보입니다. 실제로 어떤 작업이 중단되는지 확인하기 위해 로그의 어디를 봐야 할지 확실하지 않습니다.

대부분 실패하지만 간혹 성공하는 경우가 있는데, 이는 어딘가에 레이스 컨디션(race condition)이 있는 것 같습니다.

제 백트레이스는 @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/delegation.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/delegation.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'
rails_multisite-4.0.1/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'

디버깅을 돕기 위해 더 제공할 수 있는 정보가 있을까요?

4개의 좋아요
16

3개의 게시글이 기존 주제 이메일 호스트명 인증서 불일치로 인한 sidekiq 큐 과부하 및 심각한 사이트 불안정성에 병합되었습니다.

17

이 문제도 경험하고 있습니다!

18

메일 서버가 라운드 로빈에서 다른 서버의 인증서를 사용한다는 사실을 발견했고, 호스트명 불일치가 문제일 것이라고 기대했습니다. 인증서 불일치가 없는 서버로 전환하는 과정에서 b850c12793로 업데이트했지만, 문제는 해결되지 않았습니다. 일부 작업을 재시도해 보았지만, 어느 것도 성공적으로 완료되지 않았습니다. 따라서 이 버그는 숨겨진 인증서 불일치의 증상이 아닙니다.

이는 discourse_docker 2a9faf7e5680b9로 빌드되었습니다.

discourse_docker를 241a42ce718로, 그리고 discourse를 95e7e10417로 업데이트해도 문제가 해결되지 않았습니다. 여전히 이러한 실패가 30건 재시도되고 있습니다.

1개의 좋아요
19

설명해 주신 내용과 이 게시글을 살펴보면, 여러 문제가 있을 수 있습니다:

서버가 이메일 재시도(throttling)를 제한하지 않아 타임아웃이 발생하거나 메일 서버에 의해 거부되고 있을 수 있습니다. 하지만 인증서와 설정이 유효함에도 불구하고 이메일이 계속 전송되지 않는다면, 그 이면에는 다른 근본적인 문제가 있는 것입니다. 일부 사용자의 경우 디스크 공간이 계속 소모되는 현상도 보고되고 있습니다. 제 서버를 확인해 보았지만, 여기서는 그런 문제가 관찰되지 않았습니다.

20

공간이 부족해서 그런 것도 아니고, 재실행할 작업을 정확히 하나만 선택해도 같은 문제가 발생하므로 레이스 컨디션(race condition)으로 보이지 않습니다. 여기에는 분명히 여러 문제가 있으며, 제가 확인하고 있는 이 문제는 해당 링크된 주제와 무관합니다.

(결국 인증서 문제였던 것은 아니었습니다. 서버 이름은 대체 서버 이름(Alt Name)에 포함되어 있었습니다. 하지만 어쨌든 SN과 일치하는 호스트네임을 사용하도록 변경했는데, 아무런 차이가 없었습니다.)

대량의 메일을 정상적으로 전송하고 있지만, 일부 작업만 막혀 있는 상태입니다. 예를 들어, 진단을 위해 어떤 로그 항목을 찾아봐야 하는지 모르겠습니다.

2개의 좋아요
Email Hostname Certificate Mismatch Causing sidekiq Queue Overload, Severe Site Instability
24

현재 이 문제를 재현하는 실패하는 테스트를 추가하는 초안 PR을 만들었습니다:

이제 문제를 일으키는 코드 줄을 알게 되었으니, 곧 좋은 해결책을 마련할 수 있기를 바랍니다.

5개의 좋아요
26

29건의 실패한 이메일을 검토하여 중요한 내용이 있는지 확인해 보았는데, 내가 아는 한 그런 건 없었습니다. 그래서 이메일 작업이 업그레이드를 가로지르는 동안 발생하는 일시적인 문제 때문일 수도 있겠다는 생각에 sidekiq의 모든 작업을 삭제했습니다. 하지만 추가 업데이트를 적용하지 않은 상태에서 동일한 실패 사례가 다시 한 번 발생했습니다.

이것이 일시적인 이상 현상이 아니라 지속되고 있는 문제라는 정보를 공유하기 위해 이 글을 씁니다.

2개의 좋아요
27

위에서 언급한 코드 수정이 병합되었습니다. 시간이 나시면 최신 변경 사항을 git pull로 가져와서 컨테이너를 다시 빌드해 주시겠습니까?

4개의 좋아요
28

작업 업그레이드 및 재시도 후 메일 전송에 성공했습니다. 이메일 로그를 확인해 보니 전송 완료로 보고되어 있었습니다.

감사합니다!

4개의 좋아요