Lavoratori / MiniRacer::ScriptTerminatedError timeout nei /logs

Da alcuni mesi, vediamo decine di questi avvisi nei file di log (/logs) ogni giorno:

Unicorn worker received USR2 signal indicating it is about to timeout, dumping backtrace for main thread

Dato che solitamente eseguiamo la versione stable, ho ipotizzato che sarebbero scomparsi dopo il passaggio alla prossima versione principale, cosa che abbiamo fatto questa settimana. Ora siamo alla versione 3.4.1, ma gli errori persistono.

backtrace
activesupport-7.2.2.1/lib/active_support/broadcast_logger.rb:130:in `block in warn' 
activesupport-7.2.2.1/lib/active_support/broadcast_logger.rb:231:in `block in dispatch' 
activesupport-7.2.2.1/lib/active_support/broadcast_logger.rb:231:in `each' 
activesupport-7.2.2.1/lib/active_support/broadcast_logger.rb:231:in `dispatch' 
activesupport-7.2.2.1/lib/active_support/broadcast_logger.rb:130:in `warn' 
/var/www/discourse/lib/signal_trap_logger.rb:40:in `public_send' 
/var/www/discourse/lib/signal_trap_logger.rb:40:in `block (2 levels) in ensure_logging_thread_running' 
<internal:kernel>:187:in `loop'
/var/www/discourse/lib/signal_trap_logger.rb:37:in `block in ensure_logging_thread_running' 
info
Unicorn worker received USR2 signal indicating it is about to timeout, dumping backtrace for main thread
config/unicorn.conf.rb:203:in `backtrace'
config/unicorn.conf.rb:203:in `block (2 levels) in reload'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/rack-mini-profiler-3.3.1/lib/patches/db/pg.rb:69:in `exec_params'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/rack-mini-profiler-3.3.1/lib/patches/db/pg.rb:69:in `exec_params'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:894:in `block (2 levels) in exec_no_cache'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:1004:in `block in with_raw_connection'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:976:in `with_raw_connection'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:893:in `block in exec_no_cache'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:1119:in `log'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:892:in `exec_no_cache'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:872:in `execute_and_clear'
/var/www/discourse/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.2.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:66:in `internal_exec_query'
/var/www/d...

Non sono sicuro che siano correlati, ma stiamo anche osservando due classi di errori (non avvisi), che si alternano, sebbene meno frequentemente:

Job exception: terminated

backtrace
/var/www/discourse/lib/pretty_text.rb:239:in `eval' 
/var/www/discourse/lib/pretty_text.rb:239:in `block in markdown' 
/var/www/discourse/lib/pretty_text.rb:691:in `block in protect' 
/var/www/discourse/lib/pretty_text.rb:691:in `synchronize' 
/var/www/discourse/lib/pretty_text.rb:691:in `protect' 
/var/www/discourse/lib/pretty_text.rb:176:in `markdown' 
/var/www/discourse/lib/pretty_text.rb:302:in `cook' 
/var/www/discourse/app/models/post_analyzer.rb:30:in `cook' 
/var/www/discourse/app/models/post_analyzer.rb:149:in `cooked_stripped' 
/var/www/discourse/app/models/post_analyzer.rb:88:in `raw_mentions' 
/var/www/discourse/app/models/post.rb:310:in `public_send' 
/var/www/discourse/app/models/post.rb:310:in `block (2 levels) in <class:Post>' 
/var/www/discourse/app/services/post_alerter.rb:735:in `extract_mentions' 
/var/www/discourse/app/services/post_alerter.rb:174:in `after_save_post' 
/var/www/discourse/app/jobs/regular/post_alert.rb:10:in `execute' 
/var/www/discourse/app/jobs/base.rb:316:in `block (2 levels) in perform' 
rails_multisite-6.1.0/lib/rails_multisite/connection_management/null_instance.rb:49:in `with_connection'
rails_multisite-6.1.0/lib/rails_multisite/connection_management.rb:21:in `with_connection'
/var/www/discourse/app/jobs/base.rb:303:in `block in perform' 
/var/www/discourse/app/jobs/base.rb:299:in `each' 
/var/www/discourse/app/jobs/base.rb:299:in `perform' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:202:in `execute_job' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:170:in `block (2 levels) in process' 
sidekiq-6.5.12/lib/sidekiq/middleware/chain.rb:177:in `block in invoke' 
/var/www/discourse/lib/sidekiq/pausable.rb:132:in `call' 
sidekiq-6.5.12/lib/sidekiq/middleware/chain.rb:179:in `block in invoke' 
sidekiq-6.5.12/lib/sidekiq/middleware/chain.rb:182:in `invoke' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:169:in `block in process' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:136:in `block (6 levels) in dispatch' 
sidekiq-6.5.12/lib/sidekiq/job_retry.rb:113:in `local' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:135:in `block (5 levels) in dispatch' 
sidekiq-6.5.12/lib/sidekiq.rb:44:in `block in <module:Sidekiq>' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:131:in `block (4 levels) in dispatch' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:263:in `stats' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:126:in `block (3 levels) in dispatch' 
sidekiq-6.5.12/lib/sidekiq/job_logger.rb:13:in `call' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:125:in `block (2 levels) in dispatch' 
sidekiq-6.5.12/lib/sidekiq/job_retry.rb:80:in `global' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:124:in `block in dispatch' 
sidekiq-6.5.12/lib/sidekiq/job_logger.rb:39:in `prepare' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:123:in `dispatch' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:168:in `process' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:78:in `process_one' 
sidekiq-6.5.12/lib/sidekiq/processor.rb:68:in `run' 
sidekiq-6.5.12/lib/sidekiq/component.rb:8:in `watchdog' 
sidekiq-6.5.12/lib/sidekiq/component.rb:17:in `block in safe_thread
info
Job exception: terminated

E inoltre,

MiniRacer::ScriptTerminatedError (terminated) lib/pretty_text.rb:239:in eval' lib/pretty_text.rb:239:in block in markdown’ lib/pretty_text.rb:691:in block in protect' lib/pretty_text.rb:691:in syn

backtrace
lib/pretty_text.rb:239:in `eval'
lib/pretty_text.rb:239:in `block in markdown'
lib/pretty_text.rb:691:in `block in protect'
lib/pretty_text.rb:691:in `synchronize'
lib/pretty_text.rb:691:in `protect'
lib/pretty_text.rb:176:in `markdown'
lib/pretty_text.rb:302:in `cook'
app/models/post_analyzer.rb:30:in `cook'
app/models/post_analyzer.rb:149:in `cooked_stripped'
app/models/post_analyzer.rb:88:in `raw_mentions'
app/models/post.rb:310:in `public_send'
app/models/post.rb:310:in `block (2 levels) in <class:Post>'
lib/validators/post_validator.rb:80:in `max_mention_validator'
lib/validators/post_validator.rb:17:in `validate'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:385:in `block in make_lambda'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:179:in `block in call'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:668:in `block (2 levels) in default_terminator'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:667:in `catch'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:667:in `block in default_terminator'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:180:in `call'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:559:in `block in invoke_before'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:559:in `each'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:559:in `invoke_before'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:109:in `run_callbacks'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:913:in `_run_validate_callbacks'
activemodel (7.2.2.1) lib/active_model/validations.rb:441:in `run_validations!'
activemodel (7.2.2.1) lib/active_model/validations/callbacks.rb:115:in `block in run_validations!'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:110:in `run_callbacks'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:913:in `_run_validation_callbacks'
activemodel (7.2.2.1) lib/active_model/validations/callbacks.rb:115:in `run_validations!'
activemodel (7.2.2.1) lib/active_model/validations.rb:366:in `valid?'
activerecord (7.2.2.1) lib/active_record/validations.rb:71:in `valid?'
activerecord (7.2.2.1) lib/active_record/validations.rb:91:in `perform_validations'
activerecord (7.2.2.1) lib/active_record/validations.rb:48:in `save'
activerecord (7.2.2.1) lib/active_record/transactions.rb:362:in `block in save'
activerecord (7.2.2.1) lib/active_record/transactions.rb:418:in `block (2 levels) in with_transaction_returning_status'
activerecord (7.2.2.1) lib/active_record/connection_adapters/abstract/database_statements.rb:359:in `transaction'
activerecord (7.2.2.1) lib/active_record/transactions.rb:414:in `block in with_transaction_returning_status'
activerecord (7.2.2.1) lib/active_record/connection_adapters/abstract/connection_pool.rb:415:in `with_connection'
activerecord (7.2.2.1) lib/active_record/connection_handling.rb:296:in `with_connection'
activerecord (7.2.2.1) lib/active_record/transactions.rb:410:in `with_transaction_returning_status'
activerecord (7.2.2.1) lib/active_record/transactions.rb:362:in `save'
activerecord (7.2.2.1) lib/active_record/suppressor.rb:52:in `save'
lib/post_revisor.rb:499:in `update_post'
lib/post_revisor.rb:460:in `revise'
lib/post_revisor.rb:454:in `revise_and_create_new_version'
lib/post_revisor.rb:357:in `revise_post'
lib/post_revisor.rb:279:in `block in revise!'
activerecord (7.2.2.1) lib/active_record/connection_adapters/abstract/transaction.rb:616:in `block in within_new_transaction'
activesupport (7.2.2.1) lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
activerecord (7.2.2.1) lib/active_record/connection_adapters/abstract/transaction.rb:613:in `within_new_transaction'
activerecord (7.2.2.1) lib/active_record/connection_adapters/abstract/database_statements.rb:361:in `transaction'
activerecord (7.2.2.1) lib/active_record/transactions.rb:234:in `block in transaction'
activerecord (7.2.2.1) lib/active_record/connection_adapters/abstract/connection_pool.rb:415:in `with_connection'
activerecord (7.2.2.1) lib/active_record/connection_handling.rb:296:in `with_connection'
activerecord (7.2.2.1) lib/active_record/transactions.rb:233:in `transaction'
lib/post_revisor.rb:278:in `revise!'
app/controllers/posts_controller.rb:276:in `update'
actionpack (7.2.2.1) lib/action_controller/metal/basic_implicit_render.rb:8:in `send_action'
actionpack (7.2.2.1) lib/abstract_controller/base.rb:226:in `process_action'
actionpack (7.2.2.1) lib/action_controller/metal/rendering.rb:193:in `process_action'
actionpack (7.2.2.1) lib/abstract_controller/callbacks.rb:261:in `block in process_action'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:121:in `block in run_callbacks'
app/controllers/application_controller.rb:427:in `block in with_resolved_locale'
i18n (1.14.7) lib/i18n.rb:353:in `with_locale'
app/controllers/application_controller.rb:427:in `with_resolved_locale'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:130:in `block in run_callbacks'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:141:in `run_callbacks'
actionpack (7.2.2.1) lib/abstract_controller/callbacks.rb:260:in `process_action'
actionpack (7.2.2.1) lib/action_controller/metal/rescue.rb:27:in `process_action'
actionpack (7.2.2.1) lib/action_controller/metal/instrumentation.rb:77:in `block in process_action'
activesupport (7.2.2.1) lib/active_support/notifications.rb:210:in `block in instrument'
activesupport (7.2.2.1) lib/active_support/notifications/instrumenter.rb:58:in `instrument'
activesupport (7.2.2.1) lib/active_support/notifications.rb:210:in `instrument'
actionpack (7.2.2.1) lib/action_controller/metal/instrumentation.rb:76:in `process_action'
actionpack (7.2.2.1) lib/action_controller/metal/params_wrapper.rb:259:in `process_action'
activerecord (7.2.2.1) lib/active_record/railties/controller_runtime.rb:39:in `process_action'
actionpack (7.2.2.1) lib/abstract_controller/base.rb:163:in `process'
actionview (7.2.2.1) lib/action_view/rendering.rb:40:in `process'
rack-mini-profiler (3.3.1) lib/mini_profiler/profiling_methods.rb:89:in `block in profile_method' 
actionpack (7.2.2.1) lib/action_controller/metal.rb:252:in `dispatch'
actionpack (7.2.2.1) lib/action_controller/metal.rb:335:in `dispatch'
actionpack (7.2.2.1) lib/action_dispatch/routing/route_set.rb:67:in `dispatch'
actionpack (7.2.2.1) lib/action_dispatch/routing/route_set.rb:50:in `serve'
actionpack (7.2.2.1) lib/action_dispatch/journey/router.rb:53:in `block in serve'
actionpack (7.2.2.1) lib/action_dispatch/journey/router.rb:133:in `block in find_routes'
actionpack (7.2.2.1) lib/action_dispatch/journey/router.rb:126:in `each'
actionpack (7.2.2.1) lib/action_dispatch/journey/router.rb:126:in `find_routes'
actionpack (7.2.2.1) lib/action_dispatch/journey/router.rb:34:in `serve'
actionpack (7.2.2.1) lib/action_dispatch/routing/route_set.rb:896:in `call'
lib/middleware/omniauth_bypass_middleware.rb:64:in `call'
rack (2.2.10) lib/rack/tempfile_reaper.rb:15:in `call'
rack (2.2.10) lib/rack/conditional_get.rb:40:in `call'
rack (2.2.10) lib/rack/head.rb:12:in `call'
actionpack (7.2.2.1) lib/action_dispatch/http/permissions_policy.rb:38:in `call'
lib/content_security_policy/middleware.rb:12:in `call'
lib/middleware/anonymous_cache.rb:403:in `call'
lib/middleware/csp_script_nonce_injector.rb:12:in `call'
config/initializers/008-rack-cors.rb:14:in `call'
rack (2.2.10) lib/rack/session/abstract/id.rb:266:in `context'
rack (2.2.10) lib/rack/session/abstract/id.rb:260:in `call'
actionpack (7.2.2.1) lib/action_dispatch/middleware/cookies.rb:704:in `call'
actionpack (7.2.2.1) lib/action_dispatch/middleware/callbacks.rb:31:in `block in call'
activesupport (7.2.2.1) lib/active_support/callbacks.rb:101:in `run_callbacks'
actionpack (7.2.2.1) lib/action_dispatch/middleware/callbacks.rb:30:in `call'
actionpack (7.2.2.1) lib/action_dispatch/middleware/debug_exceptions.rb:31:in `call'
actionpack (7.2.2.1) lib/action_dispatch/middleware/show_exceptions.rb:32:in `call'
logster (2.20.0) lib/logster/m
info
MiniRacer::ScriptTerminatedError (terminated)
lib/pretty_text.rb:239:in `eval'
lib/pretty_text.rb:239:in `block in markdown'
lib/pretty_text.rb:691:in `block in protect'
lib/pretty_text.rb:691:in `synchronize'
lib/pretty_text.rb:691:in `protect'
lib/pretty_text.rb:176:in `markdown'
lib/pretty_text.rb:302:in `cook'
app/models/post_analyzer.rb:30:in `cook'
app/models/post_analyzer.rb:149:in `cooked_stripped'
app/models/post_analyzer.rb:88:in `raw_mentions'
app/models/post.rb:310:in `public_send'
app/models/post.rb:310:in `block (2 levels) in <class:Post>'
lib/validators/post_validator.rb:80:in `max_mention_validator'
lib/validators/post_validator.rb:17:in `validate'
lib/post_revisor.rb:499:in `update_post'
lib/post_revisor.rb:460:in `revise'
lib/post_revisor.rb:454:in `revise_and_create_new_version'
lib/post_revisor.rb:357:in `revise_post'
lib/post_revisor.rb:279:in `block in revise!'
lib/post_revisor.rb:278:in `revise!'
app/controllers/posts_controller.rb:276:in `update'
app/controllers/application_controller.rb:427:in `block in with_resolved_locale'
app/controllers/application_controller.rb:427:in `with_resolved_locale'
lib/middleware/omniauth_bypass_middleware.rb:64:in `call'
lib/content_security_policy/middleware.rb:12:in `call'
lib/middleware/anonymous_cache.rb:403:in `call'
lib/middleware/csp_script_nonce_injector.rb:12:in `call'
config/initializers/008-rack-cors.rb:14:in `call'
config/initializers/100-quiet_logger.rb:20:in `call'
config/initializers/100-silence_logger.rb:29:in `call'
lib/middleware/enforce_hostname.rb:24:in `call'
lib/middleware/processing_request.rb:12:in `call'
lib/middleware/request_tracker.rb:385:in `call'

Questi potrebbero essere correlati a questo, ma nel mio caso sembrano persistere. Inoltre, come menzionato lì, i log sembrano essere talvolta troncati.

Ecco come appare tutto questo nei file di log (/logs):

Avete qualche indizio su cosa possa causare questi problemi? Posso fornire altre informazioni?

Stiamo riscontrando lo stesso errore sulla nostra istanza quando pubblichiamo/modifica/approviamo un argomento con contenuti Markdown molto specifici. Si caricherà per un po’ e poi genererà un errore interno del server.

Per quanto mi riguarda, abbiamo anche ricevuto segnalazioni sporadiche da utenti con errori simili durante la modifica di alcuni post (di solito piuttosto lunghi, anche se non vicini al limite), dove apportare piccole modifiche al testo sembra superare l’errore (aneddoticamente: aggiungere un altro punto, sostituire un trattino, ecc.). Non siamo ancora riusciti a trovare passaggi riproducibili poiché di solito ne vengo a conoscenza solo quando qualcuno ha trovato il “trucco magico”.

Ho appena notato anche questi avvisi. Quando iniziano, possono verificarsi diverse ricorrenze nel giro di un’ora circa, poi si fermano. Fino alla prossima volta. Giurerei che non li avevamo fino a pochi giorni fa.

Su quale versione siete, @icaria36 e @Indra? Noi siamo su stable, ma mi chiedo se questo stia succedendo anche in tests-passed.

Siamo alla versione 3.5.0.beta3-dev (3f353a726b).

Penso di aver trovato qualcosa di probabile correlazione e che potrebbe fornire ulteriori indizi sulla fonte del problema. Diventa un po’ prolisso, quindi abbiate pazienza.

Oggi ho notato che ho un paio di job sidekiq che falliscono e vengono ritentati da almeno una settimana con lo stesso errore presente in /logs.

Nella console, se provo a rifare il “rebake” di quel post specifico, ci vuole molto tempo (quasi 30 secondi) e alla fine termina con

errore
lib/pretty_text.rb:239:in `eval': terminated (MiniRacer::ScriptTerminatedError)
	from lib/pretty_text.rb:239:in `block in markdown'
	from lib/pretty_text.rb:691:in `block in protect'
	from lib/pretty_text.rb:691:in `synchronize'
	from lib/pretty_text.rb:691:in `protect'
	from lib/pretty_text.rb:176:in `markdown'
	from lib/pretty_text.rb:302:in `cook'
	from app/models/post_analyzer.rb:30:in `cook'
	from app/models/post.rb:357:in `cook'
	from app/models/post.rb:825:in `rebake!'
	from (discourse):1:in `<main>'

Dopo alcuni esperimenti, sembra che sia dovuto a un particolare riferimento di caricamento che viene utilizzato più volte (oltre 25) nello stesso post:

Il tempo necessario per il “rebake” del post è proporzionale al numero di volte in cui quell’immagine viene referenziata in esso (da 1 a 2 secondi per ogni utilizzo). Se viene menzionata abbastanza volte, alla fine si verifica l’errore di timeout. Tuttavia, se un’altra immagine caricata viene menzionata un numero di volte uguale o maggiore, il “rebake” è sempre istantaneo.

Salvare la stessa immagine e caricarla di nuovo non riproduce il problema. Quindi il problema sembra essere con un particolare riferimento di caricamento.

Se tutto questo non fosse già abbastanza strano, diventa ancora più bizzarro. Notando che l’immagine ri-caricata includeva l’estensione del file nel riferimento di caricamento, ho provato ad aggiungere .gif al riferimento di caricamento problematico e… poi il “rebake” funziona istantaneamente come dovrebbe, anche quando la stessa immagine problematica viene utilizzata decine di volte. In altre parole, ho cambiato qualcosa come

![foobar|15x15](upload://w5ilVpOCq4ZcvEahAisyiR1pzhu)

in

![foobar|15x15](upload://w5ilVpOCq4ZcvEahAisyiR1pzhu.gif)

e, in qualche modo, questo ha fatto scomparire questo strano errore di timeout.

Ipotesi: è necessario rielaborare questa immagine e0ded3304aff1477bae442c0ead0050210dce4f0 e per qualche motivo fallisce ripetutamente, prolungando il processo di “baking” abbastanza a lungo da fallire alla fine? Non sono sicuro di come procedere da qui.

In ogni caso, questo sembra un bug che meriterebbe attenzione – forse i @moderators possono spostarlo in Bug se sono d’accordo?