Ao postar usando a API, aparece um aviso de erro

Sempre que publicar via API, o seguinte aviso de erro aparece nos logs:

DistributedMutex(“memoize_lock_post##2f7d40f44a4b0fa66a711ca8f2ff9278fed9fa72”): mantido por tempo excessivo, máximo esperado: 1 seg, levou 1 seg a mais

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

Isso provavelmente não é causado diretamente pelo proxy reverso.

Para posts criados via API, o Discourse utiliza o DistributedMemoizer ao redor de PostsController#create para evitar a criação duplicada de posts pela API. Esse memoizer usa um DistributedMutex baseado em Redis com um tempo de validade muito curto de 1 segundo. O aviso indica que o trabalho de criação/serialização do post dentro dessa trava levou mais tempo do que o esperado.

Portanto:

  • se o post da API for criado com sucesso, trata-se de um aviso e não da falha raiz;
  • expected max: 1 secs, took an extra 1 secs significa que a trava foi mantida por aproximadamente 2 segundos;
  • é mais provável que esteja relacionado ao desempenho do servidor, latência do Redis/Postgres, E/S de disco, pressão de CPU/RAM, plugins ou processamento lento do post do que ao próprio proxy reverso nginx/1Panel;
  • o motivo de aparecer apenas para postagem via API é que esse caminho do memoizer é utilizado para solicitações da API.

Coisas que valem a pena verificar:

  1. A solicitação da API tem sucesso e cria apenas um post?
  2. Quanto tempo a solicitação da API leva do lado do cliente?
  3. CPU, memória, swap ou E/S de disco estão saturados durante a postagem via API?
  4. O Redis e o Postgres estão dentro do mesmo container/host e estão saudáveis?
  5. O aviso ainda ocorre com um post de texto simples muito pequeno, sem imagens/uploads?
  6. Há plugins não padrão instalados?

Como se trata de uma implantação via 1Panel/container e não da instalação padrão do Discourse via Docker, também pode ser útil reproduzir o problema em uma instalação oficialmente suportada, se possível, antes de tratá-lo como um bug do núcleo do Discourse.