Travailleurs / MiniRacer::ScriptTerminatedError délais d'expiration dans /logs

Depuis quelques mois, nous voyons ces dizaines d’avertissements dans /logs chaque jour :

Un worker Unicorn a reçu le signal USR2 indiquant qu’il est sur le point de dépasser le délai imparti, et a vidé la trace d’appel du thread principal.

Comme nous fonctionnons habituellement sur stable, j’ai supposé qu’ils finiraient par disparaître lorsque nous passerions à la prochaine version majeure, ce que nous avons fait cette semaine. Nous sommes maintenant sur la version 3.4.1, mais les erreurs persistent.

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
Un worker Unicorn a reçu le signal USR2 indiquant qu'il est sur le point de dépasser le délai imparti, et a vidé la trace d'appel du thread principal
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...

Je ne suis pas sûr qu’ils soient liés, mais nous constatons également deux classes d’erreurs (et non d’avertissements), mélangées, bien que moins fréquemment :

Exception de tâche : terminée

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
Exception de tâche : terminée

Et aussi,

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'

Ces erreurs peuvent être liées à ceci, mais dans mon cas, elles semblent persister. Et, comme mentionné là-bas, les journaux semblent parfois être tronqués.

Et voici à quoi tout cela ressemble dans /logs :

Avez-vous des indices sur ce qui pourrait causer cela ? Puis-je fournir d’autres informations ?

Je rencontre la même erreur sur notre instance lors de la publication/modification/approbation d’un sujet avec un contenu Markdown très spécifique. Il se charge pendant un moment puis renvoie une erreur interne du serveur.

Pour information, nous avons également vu des rapports sporadiques d’utilisateurs avec des erreurs similaires lors de la modification de certains messages (généralement assez longs, bien que pas proches de la limite), où de minuscules modifications au texte semblent surmonter l’erreur (anecdotiquement : ajouter un point, remplacer un tiret, etc.). Je n’ai pas encore trouvé d’étapes reproductibles car j’en entends généralement parler uniquement lorsqu’une personne a trouvé le « truc magique ».

J’ai également remarqué ces avertissements. Lorsqu’ils commencent, ils peuvent se répéter plusieurs fois en une heure environ, puis s’arrêter. Jusqu’à la prochaine fois. Je jurerais que nous ne les avions pas il y a quelques jours.

Sur quelle version êtes-vous, @icaria36 et @Indra ? Nous sommes sur stable, mais je me demande si cela se produit également dans tests-passed.

Nous sommes sur la version 3.5.0.beta3-dev (3f353a726b).

Je pense avoir trouvé quelque chose qui est probablement lié à ce problème et qui pourrait fournir de nouvelles indices sur l’origine du souci. Cela va devenir un peu long, alors veuillez m’excuser.

J’ai remarqué aujourd’hui que j’ai quelques tâches Sidekiq qui échouent et qui sont en cours de réessai depuis au moins une semaine avec la même erreur que celle affichée dans /logs.

Dans la console, si je tente de récuire (rebake) ce post spécifique, cela prend beaucoup de temps (près de 30 secondes) et finit par échouer avec :

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

Après quelques expérimentations, il semble que cela soit dû à une référence d’upload spécifique qui est utilisée à plusieurs reprises (plus de 25 fois) dans le même post :

Le temps nécessaire pour récuire le post est proportionnel au nombre de fois où cette image est référencée (1 à 2 secondes par utilisation). Si elle est mentionnée suffisamment de fois, cela finit par déclencher une erreur de dépassement de délai. Cependant, si une autre image téléchargée est mentionnée autant ou plus souvent, la recuisson est toujours instantanée.

Sauvegarder la même image et la téléverser à nouveau ne reproduit pas le problème. Le souci semble donc être lié à une référence d’upload spécifique.

Si tout cela n’est pas déjà assez étrange, c’est encore plus bizarre. En remarquant que l’image re-téléversée incluait l’extension du fichier dans la référence d’upload, j’ai essayé d’ajouter .gif à la référence problématique… et là, la recuisson fonctionne instantanément comme il se doit – même lorsque la même image problématique est utilisée des dizaines de fois. Autrement dit, j’ai modifié quelque chose comme

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

en

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

et, d’une manière ou d’une autre, cela a fait disparaître cette erreur de dépassement de délai bizarre.

Hypothèse : un nouveau traitement doit être effectué sur cette image e0ded3304aff1477bae442c0ead0050210dce4f0 et, pour une raison inconnue, cela échoue à plusieurs reprises, prolongeant le processus de recuisson au point qu’il finisse par échouer ? Je ne sais pas trop comment procéder à partir d’ici.

En tout cas, cela semble être un bug qui mérite une attention particulière – peut-être que les @modérateurs pourront le déplacer vers Contribute > Bug s’ils sont d’accord ?