Errore di nuovo tentativo in sidekiq

È la prima volta che vedo questo errore dopo il recente aggiornamento a 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

Se provo a ritentare, fallisce di nuovo. Sembra riferirsi a un nuovo argomento creato da un utente.

Cosa significa e come posso risolvere?

2 Mi Piace

Sto vedendo che il server ha inviato con successo molte email per questo nuovo argomento a tutti coloro che stavano monitorando quella categoria, non vedo nemmeno errori nei log delle email o sul server di posta elettronica.

Quindi a cosa si riferisce questo?

Stesso errore per la prima volta di questo tipo qui, riprovare non aiuta, tutte le altre email sono state consegnate:

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

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

Ho appena notato anche i log di discourse:

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

Spostamento questo nei bug invece che nel supporto

1 Mi Piace

Ciao @RBoy :slight_smile:

Stai ancora riscontrando questo errore?

Per quella voce sì, era ancora bloccata in un ciclo di ripetizione fino a ieri, quando dopo centinaia di tentativi mi sono finalmente stancato e l’ho eliminata. Spero di non aver rotto qualcosa.

Non l’ho più vista, ma poi non c’è stato un evento che abbia scatenato centinaia di email su un singolo post. Sarebbe comunque bello capire da dove è venuta e cosa significa.

Qualche giorno fa, ho riscontrato questo errore su tre messaggi e non erano critici, quindi ho eliminato i processi dopo che un nuovo tentativo non è andato a buon fine.

Ora ne ho 2001 e il mio account di test non ha ricevuto un riepilogo settimanale che avrebbe dovuto ricevere.

Sto eseguendo 8695449cfc in questo momento.

2 Mi Piace

Ho effettuato l’aggiornamento a bf987af3ca e ho ritentato tutto, ma ho ancora almeno 38 Jobs::HandledExceptionWrapper: Wrapped ActiveRecord::RecordInvalid: Validation failed: Post has already been taken che appaiono nella mia console sidekiq.

2 Mi Piace

Senza ulteriori aggiornamenti, ora sono sceso a 30. Suppongo che stiano andando in timeout, tranne per il fatto che il mio account di prova ha ricevuto il riepilogo settimanale (ritardato), e immagino che questo sia correlato. Non sono sicuro di dove guardare nei log per sapere se qualcuno sta effettivamente rinunciando.

Sembrano fallire per lo più ma occasionalmente avere successo, il che sicuramente suggerisce una race condition da qualche parte.

Le mie backtrace sembrano le stesse di quelle che @RBoy e @md-misko hanno visto, ma ecco la backtrace completa, non solo quella troncata dal pulsante “Copia”:

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

C’è qualche altra informazione che potrei fornire per aiutare nel debug?

4 Mi Piace

3 post sono stati uniti a un argomento esistente: Email Hostname Certificate Mismatch Causing sidekiq Queue Overload, Severe Site Instability

Sto riscontrando questo problema anch’io!

Ho scoperto che il mio server di posta stava utilizzando un certificato per un altro server nel suo round-robin, e speravo che la discrepanza dell’hostname fosse il problema. Ho aggiornato a b850c12793 nel processo di passaggio a un server che non aveva una discrepanza di certificato, ma non ha risolto il problema. Ho ritentato alcuni dei processi, ma nessuno di essi è stato completato con successo. Pertanto, questo bug non è un sintomo di discrepanze di certificato nascoste.

Questo è stato creato con discourse_docker 2a9faf7e5680b9.

L’aggiornamento di discourse_docker a 241a42ce718, e con esso discourse a 95e7e10417, non ha risolto il problema. Ho ancora 30 di questi fallimenti in fase di ritentativo.

1 Mi Piace

Da quello che descrivi e guardando questo post, potrebbero esserci diversi problemi qui:

Il server potrebbe non limitare i tentativi di invio delle email, causando il timeout o il rifiuto da parte del server di posta. Ma c’è qualche altro problema sottostante se i tuoi certificati e la configurazione sono validi e non invia comunque le email. Per alcuni sembra anche che stia consumando spazio su disco. Ho controllato il mio ma non l’ho notato qui.

Non ho esaurito lo spazio e questo accade anche quando seleziono esattamente un’attività da rieseguire, quindi non sembra una race condition. Ci sono chiaramente più problemi qui e quello che vedo non è correlato all’argomento collegato.

(Si è scoperto che non avevo un problema di certificato, dopotutto; i nomi del server erano nel nome alternativo del server. Ma sono passato comunque all’utilizzo del nome host che corrisponde al SN, e non ha fatto alcuna differenza.)

Sto inviando con successo un numero enorme di email, solo questi pochi processi sono bloccati. Non so, ad esempio, quali voci di log cercare per aiutare la diagnosi.

2 Mi Piace

Ho creato una bozza di PR per ora che aggiunge un test fallito che replica questo problema:

Ora che sappiamo quale riga di codice sta causando il problema, speriamo di poter trovare presto una buona soluzione.

5 Mi Piace

Ho esaminato le mie 29 email fallite per assicurarmi che non ci fosse nulla di critico da inviare e, per quanto ne so, non c’era nulla, quindi ho eliminato tutti i processi in sidekiq, nel caso in cui ciò fosse dovuto a un problema transitorio dovuto a processi email che attraversano gli aggiornamenti. Tuttavia, senza applicare ulteriori aggiornamenti, ho ora un altro singolo caso dello stesso fallimento.

Condivido solo questo come informazione sul fatto che si tratta di un problema in corso e non di un problema transitorio insolito.

2 Mi Piace

La correzione del codice sopra è stata unita, puoi fare git pull delle ultime modifiche e ricompilare il tuo container quando hai un momento?

4 Mi Piace

L’aggiornamento e il nuovo tentativo del processo sono riusciti nell’invio dell’email; ho controllato i log delle email e risulta inviata.

Grazie!

4 Mi Piace