From e9ea09d17398763ead69ca845c7aefebf266d373 Mon Sep 17 00:00:00 2001 From: Daigo 3 Dango Date: Fri, 10 Jan 2020 15:15:03 -1000 Subject: [PATCH] Suppress backtrace when delivering toots (#12798) This is to suppress irrelevant backtrace from errors raised when delivering toots to remote servers. The errors are usually out of control by the local server and backtraces don't provide much information. This is similar to https://github.com/tootsuite/mastodon/pull/5174 and shortens backtraces like below: ``` WARN: Mastodon::UnexpectedResponseError: https://example.com/inbox returned code 523 WARN: app/workers/activitypub/delivery_worker.rb:48:in `block (3 levels) in perform_request' app/lib/request.rb:75:in `perform' app/workers/activitypub/delivery_worker.rb:47:in `block (2 levels) in perform_request' app/lib/request_pool.rb:53:in `use' app/lib/request_pool.rb:108:in `block (2 levels) in with' vendor/bundle/ruby/2.7.0/gems/activesupport-5.2.4.1/lib/active_support/notifications.rb:170:in `instrument' app/lib/request_pool.rb:107:in `block in with' app/lib/connection_pool/shared_connection_pool.rb:21:in `block (2 levels) in with' app/lib/connection_pool/shared_connection_pool.rb:20:in `handle_interrupt' app/lib/connection_pool/shared_connection_pool.rb:20:in `block in with' app/lib/connection_pool/shared_connection_pool.rb:16:in `handle_interrupt' app/lib/connection_pool/shared_connection_pool.rb:16:in `with' app/lib/request_pool.rb:106:in `with' app/workers/activitypub/delivery_worker.rb:46:in `block in perform_request' vendor/bundle/ruby/2.7.0/gems/stoplight-2.2.0/lib/stoplight/light/runnable.rb:51:in `run_code' vendor/bundle/ruby/2.7.0/gems/stoplight-2.2.0/lib/stoplight/light/runnable.rb:42:in `run_yellow' vendor/bundle/ruby/2.7.0/gems/stoplight-2.2.0/lib/stoplight/light/runnable.rb:24:in `run' app/workers/activitypub/delivery_worker.rb:57:in `perform_request' app/workers/activitypub/delivery_worker.rb:25:in `perform' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:192:in `execute_job' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:165:in `block (2 levels) in process' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:128:in `block in invoke' vendor/bundle/ruby/2.7.0/gems/nsa-0.2.7/lib/nsa/collectors/sidekiq.rb:31:in `block in call' vendor/bundle/ruby/2.7.0/gems/nsa-0.2.7/lib/nsa/statsd/publisher.rb:27:in `statsd_time' vendor/bundle/ruby/2.7.0/gems/nsa-0.2.7/lib/nsa/collectors/sidekiq.rb:30:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke' app/lib/sidekiq_error_handler.rb:5:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke' vendor/bundle/ruby/2.7.0/gems/scout_apm-2.3.0.pre3/lib/scout_apm/background_job_integrations/sidekiq.rb:69:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke' vendor/bundle/ruby/2.7.0/gems/sidekiq-unique-jobs-6.0.18/lib/sidekiq_unique_jobs/server/middleware.rb:29:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:133:in `invoke' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:164:in `block in process' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:109:in `local' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:43:in `block in call' vendor/bundle/ruby/2.7.0/gems/activesupport-5.2.4.1/lib/active_support/execution_wrapper.rb:87:in `wrap' vendor/bundle/ruby/2.7.0/gems/activesupport-5.2.4.1/lib/active_support/reloader.rb:73:in `block in wrap' vendor/bundle/ruby/2.7.0/gems/activesupport-5.2.4.1/lib/active_support/execution_wrapper.rb:87:in `wrap' vendor/bundle/ruby/2.7.0/gems/activesupport-5.2.4.1/lib/active_support/reloader.rb:72:in `wrap' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:42:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:250:in `stats' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/job_logger.rb:8:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:74:in `global' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:125:in `block in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:48:in `with_context' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:42:in `with_job_hash_context' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:124:in `dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:163:in `process' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:83:in `process_one' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:71:in `run' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:16:in `watchdog' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:25:in `block in safe_thread' ``` ``` WARN: Stoplight::Error::RedLight: https://example.com/inbox WARN: vendor/bundle/ruby/2.7.0/gems/stoplight-2.2.0/lib/stoplight/light/runnable.rb:46:in `run_red' vendor/bundle/ruby/2.7.0/gems/stoplight-2.2.0/lib/stoplight/light/runnable.rb:25:in `run' app/workers/activitypub/delivery_worker.rb:57:in `perform_request' app/workers/activitypub/delivery_worker.rb:25:in `perform' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:192:in `execute_job' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:165:in `block (2 levels) in process' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:128:in `block in invoke' vendor/bundle/ruby/2.7.0/gems/nsa-0.2.7/lib/nsa/collectors/sidekiq.rb:31:in `block in call' vendor/bundle/ruby/2.7.0/gems/nsa-0.2.7/lib/nsa/statsd/publisher.rb:27:in `statsd_time' vendor/bundle/ruby/2.7.0/gems/nsa-0.2.7/lib/nsa/collectors/sidekiq.rb:30:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke' app/lib/sidekiq_error_handler.rb:5:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke' vendor/bundle/ruby/2.7.0/gems/scout_apm-2.3.0.pre3/lib/scout_apm/background_job_integrations/sidekiq.rb:69:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke' vendor/bundle/ruby/2.7.0/gems/sidekiq-unique-jobs-6.0.18/lib/sidekiq_unique_jobs/server/middleware.rb:29:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:133:in `invoke' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:164:in `block in process' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:109:in `local' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:43:in `block in call' vendor/bundle/ruby/2.7.0/gems/activesupport-5.2.4.1/lib/active_support/execution_wrapper.rb:87:in `wrap' vendor/bundle/ruby/2.7.0/gems/activesupport-5.2.4.1/lib/active_support/reloader.rb:73:in `block in wrap' vendor/bundle/ruby/2.7.0/gems/activesupport-5.2.4.1/lib/active_support/execution_wrapper.rb:87:in `wrap' vendor/bundle/ruby/2.7.0/gems/activesupport-5.2.4.1/lib/active_support/reloader.rb:72:in `wrap' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:42:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:250:in `stats' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/job_logger.rb:8:in `call' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:74:in `global' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:125:in `block in dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:48:in `with_context' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:42:in `with_job_hash_context' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:124:in `dispatch' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:163:in `process' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:83:in `process_one' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:71:in `run' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:16:in `watchdog' vendor/bundle/ruby/2.7.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:25:in `block in safe_thread' ``` --- app/lib/request.rb | 4 +++- app/workers/activitypub/delivery_worker.rb | 10 +++++++--- 2 files changed, 10 insertions(+), 4 deletions(-) diff --git a/app/lib/request.rb b/app/lib/request.rb index 42ccc6513..d82bbb075 100644 --- a/app/lib/request.rb +++ b/app/lib/request.rb @@ -59,7 +59,7 @@ class Request begin response = http_client.public_send(@verb, @url.to_s, @options.merge(headers: headers)) rescue => e - raise e.class, "#{e.message} on #{@url}", e.backtrace + raise e.class, "#{e.message} on #{@url}", e.backtrace[0] end begin @@ -73,6 +73,8 @@ class Request response.body_with_limit if http_client.persistent? yield response if block_given? + rescue => e + raise e.class, e.message, e.backtrace[0] ensure http_client.close unless http_client.persistent? end diff --git a/app/workers/activitypub/delivery_worker.rb b/app/workers/activitypub/delivery_worker.rb index 5457d9d4b..196af4af1 100644 --- a/app/workers/activitypub/delivery_worker.rb +++ b/app/workers/activitypub/delivery_worker.rb @@ -50,9 +50,13 @@ class ActivityPub::DeliveryWorker end end - light.with_threshold(STOPLIGHT_FAILURE_THRESHOLD) - .with_cool_off_time(STOPLIGHT_COOLDOWN) - .run + begin + light.with_threshold(STOPLIGHT_FAILURE_THRESHOLD) + .with_cool_off_time(STOPLIGHT_COOLDOWN) + .run + rescue Stoplight::Error::RedLight => e + raise e.class, e.message, e.backtrace.first(3) + end end def failure_tracker