From a84946c4f50c7dc8c5dc5c49e7f4a74e891936a5 Mon Sep 17 00:00:00 2001 From: Stephen Paul Weber Date: Tue, 19 Jul 2022 14:45:49 -0500 Subject: [PATCH] DRY up sentry and logging Wrap every blather handler in sentry setup and exception capturing so each route doesn't have to handle it seperately. panic is a last resort, usually better to return an XMPP error and report/log, so default to that. Also wraps each handler in a span. Note that for multistage command handlers this span is too long and they will want to call finish/set_span internally. --- lib/blather_client.rb | 69 +++++++++++++++++++++++++++++++++++++++++++ lib/command.rb | 37 +++++------------------ sgx_jmp.rb | 60 ++++++++++++++++++------------------- 3 files changed, 106 insertions(+), 60 deletions(-) create mode 100644 lib/blather_client.rb diff --git a/lib/blather_client.rb b/lib/blather_client.rb new file mode 100644 index 0000000..6de5c2d --- /dev/null +++ b/lib/blather_client.rb @@ -0,0 +1,69 @@ +# frozen_string_literal: true + +class BlatherClient < Blather::Client + def handle_data(stanza) + EMPromise.resolve(nil).then { + with_sentry(stanza) do |scope| + Thread.current[:log] = ::LOG.child( + transaction: scope.transaction_name + ) + super + rescue StandardError => e + handle_error(scope, stanza, e) + end + }.catch { |e| panic(e) } + end + + def with_sentry(stanza) + Sentry.clone_hub_to_current_thread + + Sentry.with_scope do |scope| + setup_scope(stanza, scope) + yield scope + ensure + scope.get_transaction&.then do |tx| + tx.set_status("ok") unless tx.status + tx.finish + end + end + end + + def setup_scope(stanza, scope) + name = stanza.respond_to?(:node) ? stanza.node : stanza.name + scope.clear_breadcrumbs + scope.set_transaction_name(name) + scope.set_user(jid: stanza.from.stripped.to_s) + + transaction = Sentry.start_transaction( + name: name, + op: "blather.handle_data" + ) + scope.set_span(transaction) if transaction + end + + def handle_error(scope, stanza, e) + log.error( + "Error raised during #{scope.transaction_name}: " \ + "#{e.class}", + e + ) + Sentry.capture_exception(e) unless e.is_a?(Sentry::Error) + scope.get_transaction&.set_status("internal_error") + return if e.respond_to?(:replied?) && e.replied? + + write stanza.as_error("internal-server-error", :cancel) + end + + def call_handler(handler, guards, stanza) + result = if guards.first.respond_to?(:to_str) + found = stanza.find(*guards) + handler.call(stanza, found) unless found.empty? + else + handler.call(stanza) unless guarded?(guards, stanza) + end + + return result unless result.is_a?(Promise) + + result.sync + end +end diff --git a/lib/command.rb b/lib/command.rb index da81162..1f5bb36 100644 --- a/lib/command.rb +++ b/lib/command.rb @@ -49,16 +49,15 @@ class Command @blather = blather @format_error = format_error @iq = iq - @log = LOG.child(node: iq.node) + @log = Thread.current[:log] || LOG end def execute StatsD.increment("command", tags: ["node:#{iq.node}"]) EMPromise.resolve(nil).then { Command.execution = self - sentry_hub catch_after(EMPromise.resolve(yield self)) - }.catch(&method(:panic)) + } end def reply(stanza=nil) @@ -85,24 +84,9 @@ class Command EMPromise.reject(FinalStanza.new(reply)) end - def sentry_hub - return @sentry_hub if @sentry_hub - - # Stored on Fiber-local in 4.3.1 and earlier - # https://github.com/getsentry/sentry-ruby/issues/1495 - @sentry_hub = Sentry.get_current_hub - raise "Sentry.init has not been called" unless @sentry_hub - - @sentry_hub.push_scope - @sentry_hub.current_scope.clear_breadcrumbs - @sentry_hub.current_scope.set_transaction_name(@iq.node) - @sentry_hub.current_scope.set_user(jid: @iq.from.stripped.to_s) - @sentry_hub - end - def customer @customer ||= @customer_repo.find_by_jid(@iq.from.stripped).then { |c| - sentry_hub.current_scope.set_user( + Sentry.set_user( id: c.customer_id, jid: @iq.from.stripped ) @@ -120,23 +104,18 @@ class Command }.catch_only(Timeout) { nil }.catch_only(FinalStanza) { |e| @blather << e.stanza }.catch do |e| - log_error(e) send_final_error(e) + EMPromise.reject(e) end end def send_final_error(e) - finish(@format_error.call(e), type: :error).catch_only(FinalStanza) do |s| - @blather << s.stanza + def e.replied? + true end - end - def log_error(e) - @log.error("Error raised during #{iq.node}: #{e.class}", e) - if e.is_a?(::Exception) - sentry_hub.capture_exception(e) - else - sentry_hub.capture_message(e.to_s) + finish(@format_error.call(e), type: :error).catch_only(FinalStanza) do |s| + @blather << s.stanza end end end diff --git a/sgx_jmp.rb b/sgx_jmp.rb index 50c1764..d349eb5 100644 --- a/sgx_jmp.rb +++ b/sgx_jmp.rb @@ -29,6 +29,10 @@ EM::Hiredis.logger = LOG StatsD.logger = LOG LOG.info "Starting" +def log + Thread.current[:log] || LOG +end + Sentry.init do |config| config.logger = LOG config.breadcrumbs_logger = [:sentry_logger] @@ -169,7 +173,7 @@ end BRAINTREE = AsyncBraintree.new(**CONFIG[:braintree]) def panic(e, hub=nil) - (Thread.current[:log] || LOG).fatal( + log.fatal( "Error raised during event loop: #{e.class}", e ) @@ -183,6 +187,19 @@ end EM.error_handler(&method(:panic)) +require_relative "lib/blather_client" +@client = BlatherClient.new + +setup( + CONFIG[:component][:jid], + CONFIG[:component][:secret], + CONFIG[:server][:host], + CONFIG[:server][:port], + nil, + nil, + async: true +) + # Infer anything we might have been notified about while we were down def catchup_notify_low_balance(db) db.query(<<~SQL).each do |c| @@ -225,7 +242,7 @@ def load_plans_to_db! end when_ready do - LOG.info "Ready" + log.info "Ready" BLATHER = self REDIS = EM::Hiredis.connect TEL_SELECTIONS = TelSelections.new @@ -251,16 +268,6 @@ when_ready do Web.run(LOG.child, *WEB_LISTEN) end -setup( - CONFIG[:component][:jid], - CONFIG[:component][:secret], - CONFIG[:server][:host], - CONFIG[:server][:port], - nil, - nil, - async: true -) - message to: /\Aaccount@/, body: /./ do |m| StatsD.increment("deprecated_account_bot") @@ -279,12 +286,11 @@ before( before nil, to: /\Acustomer_/, from: /(\A|@)#{CONFIG[:sgx]}(\/|\Z)/ do |s| StatsD.increment("stanza_customer") - sentry_hub = new_sentry_hub(s, name: "stanza_customer") - CustomerRepo.new(set_user: sentry_hub.current_scope.method(:set_user)).find( + Sentry.set_transaction_name("stanza_customer") + CustomerRepo.new(set_user: Sentry.method(:set_user)).find( s.to.node.delete_prefix("customer_") - ).then { |customer| - customer.stanza_to(s) - }.catch { |e| panic(e, sentry_hub) } + ).then { |customer| customer.stanza_to(s) } + halt end @@ -294,7 +300,7 @@ message( from: /(\A|@)#{CONFIG[:sgx]}(\/|\Z)/ ) do |m| StatsD.increment("inbound_group_text") - sentry_hub = new_sentry_hub(m, name: "inbound_group_text") + Sentry.set_transaction_name("inbound_group_text") address = m.find("ns:addresses", ns: ADDRESSES_NS).first &.find("ns:address", ns: ADDRESSES_NS) @@ -310,7 +316,7 @@ message( BLATHER << m }.catch_only(CustomerRepo::NotFound) { |e| BLATHER << m.as_error("forbidden", :auth, e.message) - }.catch { |e| panic(e, sentry_hub) } + } end # Ignore groupchat messages @@ -347,9 +353,8 @@ class CustomerExpired < StandardError; end message do |m| StatsD.increment("message") - sentry_hub = new_sentry_hub(m, name: "message") today = Time.now.utc.to_date - CustomerRepo.new(set_user: sentry_hub.current_scope.method(:set_user)) + CustomerRepo.new(set_user: Sentry.method(:set_user)) .find_by_jid(m.from.stripped).then { |customer| next customer.stanza_from(m) unless billable_message(m) @@ -372,13 +377,7 @@ message do |m| BLATHER << m.as_error("policy-violation", :wait, e.message) }.catch_only(CustomerRepo::NotFound, CustomerExpired) { |e| BLATHER << m.as_error("forbidden", :auth, e.message) - }.catch { |e| panic(e, sentry_hub) } -end - -message :error? do |m| - StatsD.increment("message_error") - - LOG.error "MESSAGE ERROR", stanza: m + } end IQ_MANAGER = SessionManager.new(self, :id) @@ -428,13 +427,12 @@ end disco_items node: "http://jabber.org/protocol/commands" do |iq| StatsD.increment("command_list") - sentry_hub = new_sentry_hub(iq, name: iq.node) reply = iq.reply reply.node = "http://jabber.org/protocol/commands" CustomerRepo.new( sgx_repo: Bwmsgsv2Repo.new, - set_user: sentry_hub.current_scope.method(:set_user) + set_user: Sentry.method(:set_user) ).find_by_jid( iq.from.stripped ).catch { @@ -450,7 +448,7 @@ disco_items node: "http://jabber.org/protocol/commands" do |iq| ) } self << reply - }.catch { |e| panic(e, sentry_hub) } + } end iq "/iq/ns:services", ns: "urn:xmpp:extdisco:2" do |iq| -- 2.45.2