Publication via API : erreur et avertissement

Soutien
1

Lorsque les publications sont effectuées via l’API, les erreurs et avertissements suivants apparaissent dans les journaux :

DistributedMutex(“memoize_lock_post##2f7d40f44a4b0fa66a711ca8f2ff9278fed9fa72”) : détenu trop longtemps, maximum attendu : 1 seconde, durée supplémentaire de 1 seconde

activesupport-8.0.5/lib/active_support/broadcast_logger.rb:218:in ‘block in ActiveSupport::BroadcastLogger#dispatch’
activesupport-8.0.5/lib/active_support/broadcast_logger.rb:217:in ‘Array#map’
activesupport-8.0.5/lib/active_support/broadcast_logger.rb:217:in ‘ActiveSupport::BroadcastLogger#dispatch’
activesupport-8.0.5/lib/active_support/broadcast_logger.rb:129:in ‘ActiveSupport::BroadcastLogger#warn’
/var/www/discourse/lib/distributed_mutex.rb:103:in ‘DistributedMutex#warn’
/var/www/discourse/lib/distributed_mutex.rb:57:in ‘block in DistributedMutex#synchronize’
/var/www/discourse/lib/distributed_mutex.rb:49:in ‘Thread::Mutex#synchronize’
/var/www/discourse/lib/distributed_mutex.rb:49:in ‘DistributedMutex#synchronize’
/var/www/discourse/lib/distributed_mutex.rb:34:in ‘DistributedMutex.synchronize’
/var/www/discourse/lib/distributed_memoizer.rb:12:in ‘DistributedMemoizer.memoize’
/var/www/discourse/app/controllers/posts_controller.rb:208:in ‘PostsController#create’
actionpack-8.0.5/lib/action_controller/metal/basic_implicit_render.rb:8:in ‘ActionController::BasicImplicitRender#send_action’
actionpack-8.0.5/lib/abstract_controller/base.rb:215:in ‘AbstractController::Base#process_action’
actionpack-8.0.5/lib/action_controller/metal/rendering.rb:193:in ‘ActionController::Rendering#process_action’
actionpack-8.0.5/lib/abstract_controller/callbacks.rb:261:in ‘block in AbstractController::Callbacks#process_action’
activesupport-8.0.5/lib/active_support/callbacks.rb:120:in ‘block in ActiveSupport::Callbacks#run_callbacks’
/var/www/discourse/app/controllers/application_controller.rb:452:in ‘block in ApplicationController#with_resolved_locale’
i18n-1.14.8/lib/i18n.rb:354:in ‘I18n::Base#with_locale’
/var/www/discourse/app/controllers/application_controller.rb:452:in ‘ApplicationController#with_resolved_locale’
activesupport-8.0.5/lib/active_support/callbacks.rb:129:in ‘block in ActiveSupport::Callbacks#run_callbacks’
/var/www/discourse/app/controllers/application_controller.rb:1103:in ‘ApplicationController#ensure_dont_cache_page’
activesupport-8.0.5/lib/active_support/callbacks.rb:129:in ‘block in ActiveSupport::Callbacks#run_callbacks’
activesupport-8.0.5/lib/active_support/callbacks.rb:140:in ‘ActiveSupport::Callbacks#run_callbacks’
actionpack-8.0.5/lib/abstract_controller/callbacks.rb:260:in ‘AbstractController::Callbacks#process_action’
actionpack-8.0.5/lib/action_controller/metal/rescue.rb:27:in ‘ActionController::Rescue#process_action’
actionpack-8.0.5/lib/action_controller/metal/instrumentation.rb:76:in ‘block in ActionController::Instrumentation#process_action’
activesupport-8.0.5/lib/active_support/notifications.rb:210:in ‘block in ActiveSupport::Notifications.instrument’
activesupport-8.0.5/lib/active_support/notifications/instrumenter.rb:58:in ‘ActiveSupport::Notifications::Instrumenter#instrument’
activesupport-8.0.5/lib/active_support/notifications.rb:210:in ‘ActiveSupport::Notifications.instrument’
actionpack-8.0.5/lib/action_controller/metal/instrumentation.rb:75:in ‘ActionController::Instrumentation#process_action’
actionpack-8.0.5/lib/action_controller/metal/params_wrapper.rb:259:in ‘ActionController::ParamsWrapper#process_action’
activerecord-8.0.5/lib/active_record/railties/controller_runtime.rb:39:in ‘ActiveRecord::Railties::ControllerRuntime#process_action’
actionpack-8.0.5/lib/abstract_controller/base.rb:152:in ‘AbstractController::Base#process’
actionview-8.0.5/lib/action_view/rendering.rb:40:in ‘ActionView::Rendering#process’
rack-mini-profiler-4.0.1/lib/mini_profiler/profiling_methods.rb:90:in ‘block in ActionController::Base#profile_method’
actionpack-8.0.5/lib/action_controller/metal.rb:252:in ‘ActionController::Metal#dispatch’
actionpack-8.0.5/lib/action_controller/metal.rb:335:in ‘ActionController::Metal.dispatch’
actionpack-8.0.5/lib/action_dispatch/routing/route_set.rb:67:in ‘ActionDispatch::Routing::RouteSet::Dispatcher#dispatch’
actionpack-8.0.5/lib/action_dispatch/routing/route_set.rb:50:in ‘ActionDispatch::Routing::RouteSet::Dispatcher#serve’
actionpack-8.0.5/lib/action_dispatch/journey/router.rb:53:in ‘block in ActionDispatch::Journey::Router#serve’
actionpack-8.0.5/lib/action_dispatch/journey/router.rb:133:in ‘block in ActionDispatch::Journey::Router#find_routes’
actionpack-8.0.5/lib/action_dispatch/journey/router.rb:126:in ‘Array#each’
actionpack-8.0.5/lib/action_dispatch/journey/router.rb:126:in ‘ActionDispatch::Journey::Router#find_routes’
actionpack-8.0.5/lib/action_dispatch/journey/router.rb:34:in ‘ActionDispatch::Journey::Router#serve’
actionpack-8.0.5/lib/action_dispatch/routing/route_set.rb:908:in ‘ActionDispatch::Routing::RouteSet#call’
/var/www/discourse/lib/middleware/omniauth_bypass_middleware.rb:35:in ‘Middleware::OmniauthBypassMiddleware#call’
/var/www/discourse/lib/middleware/crawler_hooks.rb:13:in ‘Middleware::CrawlerHooks#call’
rack-2.2.23/lib/rack/tempfile_reaper.rb:15:in ‘Rack::TempfileReaper#call’
rack-2.2.23/lib/rack/conditional_get.rb:40:in ‘Rack::ConditionalGet#call’
rack-2.2.23/lib/rack/head.rb:12:in ‘Rack::Head#call’
actionpack-8.0.5/lib/action_dispatch/http/permissions_policy.rb:38:in ‘ActionDispatch::PermissionsPolicy::Middleware#call’
/var/www/discourse/lib/content_security_policy/middleware.rb:12:in ‘ContentSecurityPolicy::Middleware#call’
/var/www/discourse/lib/middleware/anonymous_cache.rb:420:in ‘Middleware::AnonymousCache#call’
/var/www/discourse/lib/middleware/csp_script_nonce_injector.rb:12:in ‘Middleware::CspScriptNonceInjector#call’
/var/www/discourse/lib/middleware/track_view_session_id_injector.rb:12:in ‘Middleware::TrackViewSessionIdInjector#call’
/var/www/discourse/config/initializers/008-rack-cors.rb:14:in ‘Discourse::Cors#call’
rack-2.2.23/lib/rack/session/abstract/id.rb:266:in ‘Rack::Session::Abstract::Persisted#context’
rack-2.2.23/lib/rack/session/abstract/id.rb:260:in ‘Rack::Session::Abstract::Persisted#call’
actionpack-8.0.5/lib/action_dispatch/middleware/cookies.rb:706:in ‘ActionDispatch::Cookies#call’
actionpack-8.0.5/lib/action_dispatch/middleware/callbacks.rb:31:in ‘block in ActionDispatch::Callbacks#call’
activesupport-8.0.5/lib/active_support/callbacks.rb:100:in ‘ActiveSupport::Callbacks#run_callbacks’
actionpack-8.0.5/lib/action_dispatch/middleware/callbacks.rb:30:in ‘ActionDispatch::Callbacks#call’
actionpack-8.0.5/lib/action_dispatch/middleware/debug_exceptions.rb:31:in ‘ActionDispatch::DebugExceptions#call’
actionpack-8.0.5/lib/action_dispatch/middleware/show_exceptions.rb:32:in ‘ActionDispatch::ShowExceptions#call’
logster-2.21.0/lib/logster/middleware/reporter.rb:40:in ‘Logster::Middleware::Reporter#call’
/var/www/discourse/lib/middleware/default_headers.rb:13:in ‘Middleware::DefaultHeaders#call’
railties-8.0.5/lib/rails/rack/logger.rb:41:in ‘Rails::Rack::Logger#call_app’
railties-8.0.5/lib/rails/rack/logger.rb:29:in ‘Rails::Rack::Logger#call’
/var/www/discourse/config/initializers/100-quiet_logger.rb:20:in ‘DiscourseRackQuietAssetsLogger#call’
/var/www/discourse/config/initializers/100-silence_logger.rb:29:in ‘SilenceLogger#call’
actionpack-8.0.5/lib/action_dispatch/middleware/request_id.rb:34:in ‘ActionDispatch::RequestId#call’
/var/www/discourse/lib/middleware/enforce_hostname.rb:23:in ‘Middleware::EnforceHostname#call’
rack-2.2.23/lib/rack/method_override.rb:24:in ‘Rack::MethodOverride#call’
actionpack-8.0.5/lib/action_dispatch/middleware/executor.rb:16:in ‘ActionDispatch::Executor#call’
rack-2.2.23/lib/rack/sendfile.rb:127:in ‘Rack::Sendfile#call’
rack-mini-profiler-4.0.1/lib/mini_profiler.rb:191:in ‘Rack::MiniProfiler#call’
message_bus-4.5.2/lib/message_bus/rack/middleware.rb:60:in ‘MessageBus::Rack::Middleware#call’
/var/www/discourse/lib/middleware/request_tracker.rb:372:in ‘Middleware::RequestTracker#call’
actionpack-8.0.5/lib/action_dispatch/middleware/remote_ip.rb:96:in ‘ActionDispatch::RemoteIp#call’
/var/www/discourse/lib/middleware/overload_protections.rb:18:in ‘Middleware::OverloadProtections#call’
/var/www/discourse/lib/middleware/processing_request.rb:14:in ‘Middleware::ProcessingRequest#call’
railties-8.0.5/lib/rails/engine.rb:535:in ‘Rails::Engine#call’
railties-8.0.5/lib/rails/railtie.rb:226:in ‘Kernel#public_send’
railties-8.0.5/lib/rails/railtie.rb:226:in ‘Rails::Railtie.method_missing’
rack-2.2.23/lib/rack/urlmap.rb:74:in ‘block in Rack::URLMap#call’
rack-2.2.23/lib/rack/urlmap.rb:58:in ‘Array#each’
rack-2.2.23/lib/rack/urlmap.rb:58:in ‘Rack::URLMap#call’
rack-2.2.23/lib/rack/tempfile_reaper.rb:15:in ‘Rack::TempfileReaper#call’
pitchfork-0.18.2/lib/pitchfork/chunked.rb:105:in ‘Pitchfork::Chunked#call’
rack-2.2.23/lib/rack/content_length.rb:17:in ‘Rack::ContentLength#call’
pitchfork-0.18.2/lib/pitchfork/http_server.rb:868:in ‘Pitchfork::HttpServer#process_client’
pitchfork-0.18.2/lib/pitchfork/http_server.rb:1017:in ‘Pitchfork::HttpServer#worker_loop’
pitchfork-0.18.2/lib/pitchfork/http_server.rb:616:in ‘block in Pitchfork::HttpServer#spawn_worker’
pitchfork-0.18.2/lib/pitchfork/http_server.rb:1222:in ‘block in Pitchfork::HttpServer#fork_sibling’
pitchfork-0.18.2/lib/pitchfork.rb:170:in ‘block in Pitchfork.clean_fork’
pitchfork-0.18.2/lib/pitchfork.rb:168:in ‘Kernel#catch’
pitchfork-0.18.2/lib/pitchfork.rb:168:in ‘Pitchfork.clean_fork’
pitchfork-0.18.2/lib/pitchfork/http_server.rb:690:in ‘Pitchfork::HttpServer#spawn_initial_mold’
pitchfork-0.18.2/lib/pitchfork/http_server.rb:176:in ‘Pitchfork::HttpServer#start’
pitchfork-0.18.2/exe/pitchfork:110:in ‘<top (required)>’
/var/www/discourse/vendor/bundle/ruby/3.4.0/bin/pitchfork:25:in ‘Kernel#load’
/var/www/discourse/vendor/bundle/ruby/3.4.0/bin/pitchfork:25:in '< >

2

Ceci n’est probablement pas directement causé par le proxy inverse.

Pour les publications créées via l’API, Discourse utilise DistributedMemoizer autour de PostsController#create pour éviter la création en double de publications via l’API. Ce memoizer utilise un DistributedMutex basé sur Redis avec une durée de validité très courte de 1 seconde. L’avertissement indique que le travail de création ou de sérialisation de la publication à l’intérieur de ce verrou a pris plus de temps que prévu.

Ainsi :

  • si la publication via l’API est toujours créée avec succès, il s’agit d’un avertissement et non de la cause première de l’échec ;
  • expected max: 1 secs, took an extra 1 secs signifie que le verrou a été détenu pendant environ 2 secondes ;
  • il est plus probable que cela soit lié aux performances du serveur, à la latence de Redis/Postgres, aux entrées/sorties disque, à la pression sur le CPU/RAM, aux plugins ou au traitement lent des publications, plutôt qu’au proxy inverse nginx/1Panel lui-même ;
  • la raison pour laquelle cela n’apparaît que pour les publications via l’API est que ce chemin memoizer est utilisé pour les requêtes API.

Points worth checking :

  1. La requête API réussit-elle et crée-t-elle une seule publication ?
  2. Combien de temps la requête API prend-elle du côté client ?
  3. Le CPU, la mémoire, le swap ou les entrées/sorties disque sont-ils saturés lors de la publication via l’API ?
  4. Redis et Postgres sont-ils dans le même conteneur/hôte et fonctionnent-ils correctement ?
  5. L’avertissement se produit-il toujours avec une publication en texte brut très courte sans images/téléversements ?
  6. Des plugins non standard sont-ils installés ?

Puisqu’il s’agit d’un déploiement via 1Panel/conteneur plutôt que de l’installation Docker standard de Discourse, il peut également être utile de reproduire le problème sur une installation officiellement prise en charge, si possible, avant de le considérer comme un bug du noyau de Discourse.