Trabalhadores / MiniRacer::ScriptTerminatedError tempos limite em /logs

Suporte
1

For a few months now, we have been seeing these dozens of these warnings in /logs on a daily basis:

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

As we usually run on stable, I assumed they would eventually go away when we jumped into the next major version which we did this week. We are now on 3.4.1, but the errors continue.

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...

I’m not sure if they may be related, but we are also seeing two classes of errors (not warnings), intermixed, although less often:

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

And also,

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'

These may be related with this, but in my case they seem to persist. And, as mentioned there, the logs do seem to get truncated sometimes.

And what all this looks like in /logs:

Screenshot 2025-03-07 at 12.18.50
Screenshot 2025-03-07 at 12.18.502724×734 164 KB

Any clues on what might be causing these? Can I prove any other info?

2 curtidas
3

Vendo este mesmo erro em nossa instância ao postar/editar/aprovar um tópico com conteúdo Markdown muito específico. Ele carrega por um tempo e então lança um erro interno do servidor.

A imagem mostra uma caixa de diálogo com a mensagem "Erro Interno do Servidor", juntamente com um botão "OK". (Legenda gerada por IA)
A imagem mostra uma caixa de diálogo com a mensagem "Erro Interno do Servidor", juntamente com um botão "OK". (Legenda gerada por IA)785×172 10.2 KB

2 curtidas
4

Para que conste, também vimos relatos esporádicos de usuários com erros semelhantes ao editar algumas postagens (geralmente bem longas, embora não próximas do limite), onde fazer pequenas alterações no texto parecem superar o erro (anecdoticamente: adicionar outro ponto, substituir um traço, etc.). Ainda não consegui encontrar passos reproduzíveis, pois geralmente só ouço falar sobre isso quando alguém encontra o “truque mágico” para isso.

1 curtida
5

Também acabei de notar estes avisos. Quando eles começam, podem ter várias ocorrências dentro de uma hora ou mais, depois param. Até a próxima vez. Juro que não os tínhamos até alguns dias atrás.

image
image1148×508 131 KB

1 curtida
6

Em qual versão vocês estão, @icaria36 e @Indra? Estamos na stable, mas estou me perguntando se isso também está acontecendo em tests-passed.

1 curtida
7

Estamos na versão 3.5.0.beta3-dev (3f353a726b).

8

Acho que encontrei algo relacionado a isso e que pode fornecer mais pistas sobre a origem do problema. Isso fica um pouco longo, então, por favor, tenha paciência comigo.

Notei hoje que tenho alguns trabalhos do Sidekiq que falham e estão sendo retentados há pelo menos uma semana com o mesmo erro dos /logs.

Screenshot 2025-04-03 at 17.09.13
Screenshot 2025-04-03 at 17.09.132432×566 204 KB

No console, se eu tentar refazer esse post específico, leva muito tempo (quase 30s) e eventualmente termina com

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

Após alguma experimentação, parece que é devido a uma referência de upload específica que está sendo usada várias vezes (mais de 25) no mesmo post:

Screenshot 2025-04-03 at 17.11.56
Screenshot 2025-04-03 at 17.11.56116×376 6.96 KB

O tempo para refazer o post é proporcional ao número de vezes que essa imagem é referenciada nele (1-2 segundos para cada uso). Se for mencionada vezes suficientes, eventualmente atinge o erro de tempo limite. No entanto, se outra imagem carregada for mencionada tantas vezes ou mais, o refazer é sempre instantâneo.

Salvar a mesma imagem e carregá-la novamente não reproduz o problema. Portanto, o problema parece estar com uma referência de upload específica.

Se tudo isso não for estranho o suficiente, fica mais estranho. Notando que a imagem reenviada incluía a extensão do arquivo na referência de upload, tentei anexar .gif à referência de upload problemática e… então o refazer funciona instantaneamente como deveria – mesmo quando a mesma imagem problemática é usada dezenas de vezes. Em outras palavras, mudei algo como

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

para

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

e, de alguma forma, isso fez com que esse estranho erro de tempo limite desaparecesse.

Hipótese: algum reprocessamento precisa ser feito nesta imagem e0ded3304aff1477bae442c0ead0050210dce4f0 e, por algum motivo, ela falha repetidamente, estendendo o processo de cozimento o suficiente para eventualmente falhar? Não tenho certeza de como prosseguir a partir daqui.

Em qualquer caso, isso parece ser um bug que poderia receber alguma atenção – talvez os @moderators possam realocá-lo para Bug se concordarem?

1 curtida