Merge pull request #3190 from riking/thrown_logging

Delete old ErrorLog, use Logster for 500 errors

app/controllers/application_controller.rb

@@ -65,7 +65,7 @@ class ApplicationController < ActionController::Base
             ActionController::UnknownController,
             AbstractController::ActionNotFound].include? exception.class
       begin
-        ErrorLog.report_async!(exception, self, request, current_user)
+        Discourse.handle_request_exception(exception, self, request, current_user)
       rescue
         # dont care give up
       end

app/controllers/session_controller.rb

@@ -92,7 +92,7 @@ class SessionController < ApplicationController
       SingleSignOn::ACCESSORS.each do |a|
         details[a] = sso.send(a)
       end
-      Discourse.handle_exception(e, details)
+      Discourse.handle_job_exception(e, details)
 
       render text: I18n.t("sso.unknown_error"), status: 500
     end

app/jobs/base.rb

@@ -108,7 +108,7 @@ module Jobs
           begin
             retval = execute(opts)
           rescue => exc
-            Discourse.handle_exception(exc, error_context(opts))
+            Discourse.handle_job_exception(exc, error_context(opts))
           end
           return retval
         end
@@ -172,7 +172,7 @@ module Jobs
 
       if exceptions.length > 0
         exceptions.each do |exception_hash|
-          Discourse.handle_exception(exception_hash[:ex],
+          Discourse.handle_job_exception(exception_hash[:ex],
                 error_context(opts, exception_hash[:code], exception_hash[:other]))
         end
         raise HandledExceptionWrapper.new exceptions[0][:ex]

app/jobs/regular/notify_mailing_list_subscribers.rb

@@ -36,7 +36,7 @@ module Jobs
             message = UserNotifications.mailing_list_notify(user, post)
             Email::Sender.new(message, :mailing_list, user).send
           rescue => e
-            Discourse.handle_exception(e, error_context(
+            Discourse.handle_job_exception(e, error_context(
                 args,
                 "Sending post to mailing list subscribers", {
                 user_id: user.id,

app/jobs/scheduled/periodical_updates.rb

@@ -22,7 +22,7 @@ module Jobs
       unless UserAvatar.where("last_gravatar_download_attempt IS NULL").limit(1).first
         problems = Post.rebake_old(250)
         problems.each do |hash|
-          Discourse.handle_exception(hash[:ex], error_context(args, "Rebaking post id #{hash[:post].id}", post_id: hash[:post].id))
+          Discourse.handle_job_exception(hash[:ex], error_context(args, "Rebaking post id #{hash[:post].id}", post_id: hash[:post].id))
         end
       end
 
@@ -30,7 +30,7 @@ module Jobs
       problems = UserProfile.rebake_old(250)
       problems.each do |hash|
         user_id = hash[:profile].user_id
-        Discourse.handle_exception(hash[:ex], error_context(args, "Rebaking user id #{user_id}", user_id: user_id))
+        Discourse.handle_job_exception(hash[:ex], error_context(args, "Rebaking user id #{user_id}", user_id: user_id))
       end
     end
 

app/jobs/scheduled/poll_mailbox.rb

@@ -74,7 +74,7 @@ module Jobs
         client_message = RejectionMailer.send_rejection(message_template, message.from, template_args)
         Email::Sender.new(client_message, message_template).send
       else
-        Discourse.handle_exception(e, error_context(@args, "Unrecognized error type when processing incoming email", mail: mail_string))
+        Discourse.handle_job_exception(e, error_context(@args, "Unrecognized error type when processing incoming email", mail: mail_string))
       end
     end
 
@@ -91,7 +91,7 @@ module Jobs
         pop.finish
       end
     rescue Net::POPAuthenticationError => e
-      Discourse.handle_exception(e, error_context(@args, "Signing in to poll incoming email"))
+      Discourse.handle_job_exception(e, error_context(@args, "Signing in to poll incoming email"))
     end
 
   end

app/models/error_log.rb

@@ -1,94 +0,0 @@
-# TODO:
-# a mechanism to iterate through errors in reverse
-# async logging should queue, if dupe stack traces are found in batch error should be merged into prev one
-
-class ErrorLog
-
-  @lock = Mutex.new
-
-  def self.filename
-    "#{Rails.root}/log/#{Rails.env}_errors.log"
-  end
-
-  def self.clear!(_guid)
-    raise NotImplementedError
-  end
-
-  def self.clear_all!()
-    File.delete(ErrorLog.filename) if File.exists?(ErrorLog.filename)
-  end
-
-  def self.report_async!(exception, controller, request, user)
-    Thread.new do
-      report!(exception, controller, request, user)
-    end
-  end
-
-  def self.report!(exception, controller, request, user)
-    add_row!(
-      date: DateTime.now,
-      guid: SecureRandom.uuid,
-      user_id: user && user.id,
-      parameters: request && request.filtered_parameters.to_json,
-      action: controller.action_name,
-      controller: controller.controller_name,
-      backtrace: sanitize_backtrace(exception.backtrace).join("\n"),
-      message: exception.message,
-      url: "#{request.protocol}#{request.env["HTTP_X_FORWARDED_HOST"] || request.env["HTTP_HOST"]}#{request.fullpath}",
-      exception_class: exception.class.to_s
-    )
-  end
-
-  def self.add_row!(hash)
-    data = hash.to_xml(skip_instruct: true)
-    # use background thread to write the log cause it may block if it gets backed up
-    @lock.synchronize do
-      File.open(filename, "a") do |f|
-        f.flock(File::LOCK_EX)
-        f.write(data)
-        f.close
-      end
-    end
-  end
-
-
-  def self.each(&blk)
-    skip(0, &blk)
-  end
-
-  def self.skip(skip=0)
-    pos = 0
-    return [] unless File.exists?(filename)
-
-    loop do
-      lines = ""
-      File.open(self.filename, "r") do |f|
-        f.flock(File::LOCK_SH)
-        f.pos = pos
-        while !f.eof?
-          line = f.readline
-          lines << line
-          break if line.starts_with? "</hash>"
-        end
-        pos = f.pos
-      end
-      if lines != "" && skip == 0
-        h = {}
-        e = Nokogiri.parse(lines).children[0]
-        e.children.each do |inner|
-          h[inner.name] = inner.text
-        end
-        yield h
-      end
-      skip-=1 if skip > 0
-      break if lines == ""
-    end
-  end
-
-  def self.sanitize_backtrace(trace)
-    re = Regexp.new(/^#{Regexp.escape(Rails.root.to_s)}/)
-    trace.map { |line| Pathname.new(line.gsub(re, "[RAILS_ROOT]")).cleanpath.to_s }
-  end
-
-  private_class_method :sanitize_backtrace
-end

config/initializers/sidekiq.rb

@@ -33,7 +33,7 @@ if Sidekiq.server?
           manager.tick
         rescue => e
           # the show must go on
-          Discourse.handle_exception(e, {message: "While ticking scheduling manager"})
+          Discourse.handle_job_exception(e, {message: "While ticking scheduling manager"})
         end
         sleep 1
       end

lib/discourse.rb

@@ -15,7 +15,7 @@ module Discourse
   # error_context() method in Jobs::Base to pass the job arguments and any
   # other desired context.
   # See app/jobs/base.rb for the error_context function.
-  def self.handle_exception(ex, context = {}, parent_logger = nil)
+  def self.handle_job_exception(ex, context = {}, parent_logger = nil)
     context ||= {}
     parent_logger ||= SidekiqExceptionHandler
 
@@ -26,6 +26,29 @@ module Discourse
     }.merge(context))
   end
 
+  def self.handle_request_exception(ex, controller, request, current_user)
+    cm = RailsMultisite::ConnectionManagement
+    context = {
+      current_db: cm.current_db,
+      current_hostname: cm.current_hostname,
+      rails_action: controller.action_name,
+      rails_controller: controller.controller_name,
+    }
+
+    env = request.env.dup
+
+    context.each do |key, value|
+      Logster.add_to_env(env, key, value)
+    end
+
+    begin
+      Thread.current[Logster::Logger::LOGSTER_ENV] = env
+      Logster.logger.fatal("#{ex.class.to_s}: #{ex.message} in #{controller.controller_name}##{controller.action_name}")
+    ensure
+      Thread.current[Logster::Logger::LOGSTER_ENV] = nil
+    end
+  end
+
   # Expected less matches than what we got in a find
   class TooManyMatches < Exception; end
 

lib/oneboxer.rb

@@ -128,7 +128,7 @@ module Oneboxer
       }
     }
   rescue => e
-    Discourse.handle_exception(e, message: "While trying to onebox a URL", url: url)
+    Discourse.handle_job_exception(e, message: "While trying to onebox a URL", url: url)
     # return a blank hash, so rest of the code works
     {preview: "", onebox: ""}
   end

lib/scheduler/defer.rb

@@ -67,10 +67,10 @@ module Scheduler
         RailsMultisite::ConnectionManagement.establish_connection(db: db) if db
         job.call
       rescue => ex
-        Discourse.handle_exception(ex, {message: "Running deferred code '#{desc}'"})
+        Discourse.handle_job_exception(ex, {message: "Running deferred code '#{desc}'"})
       end
     rescue => ex
-      Discourse.handle_exception(ex, {message: "Processing deferred code queue"})
+      Discourse.handle_job_exception(ex, {message: "Processing deferred code queue"})
     ensure
       ActiveRecord::Base.connection_handler.clear_active_connections!
     end

lib/scheduler/manager.rb

@@ -42,13 +42,13 @@ module Scheduler
       def keep_alive
         @manager.keep_alive
       rescue => ex
-        Discourse.handle_exception(ex, {message: "Scheduling manager keep-alive"})
+        Discourse.handle_job_exception(ex, {message: "Scheduling manager keep-alive"})
       end
 
       def reschedule_orphans
         @manager.reschedule_orphans!
       rescue => ex
-        Discourse.handle_exception(ex, {message: "Scheduling manager orphan rescheduler"})
+        Discourse.handle_job_exception(ex, {message: "Scheduling manager orphan rescheduler"})
       end
 
       def process_queue
@@ -66,7 +66,7 @@ module Scheduler
           # Discourse.handle_exception was already called, and we don't have any extra info to give
           failed = true
         rescue => e
-          Discourse.handle_exception(e, {message: "Running a scheduled job", job: klass})
+          Discourse.handle_job_exception(e, {message: "Running a scheduled job", job: klass})
           failed = true
         end
         duration = ((Time.now.to_f - start) * 1000).to_i
@@ -77,7 +77,7 @@ module Scheduler
           @mutex.synchronize { info.write! }
         end
       rescue => ex
-        Discourse.handle_exception(ex, {message: "Processing scheduled job queue"})
+        Discourse.handle_job_exception(ex, {message: "Processing scheduled job queue"})
       ensure
         @running = false
       end

spec/components/discourse_spec.rb

@@ -139,7 +139,7 @@ describe Discourse do
     it "should not fail when called" do
       exception = StandardError.new
 
-      Discourse.handle_exception(exception, nil, nil)
+      Discourse.handle_job_exception(exception, nil, nil)
       expect(logger.exception).to eq(exception)
       expect(logger.context.keys).to eq([:current_db, :current_hostname])
     end
@@ -147,7 +147,7 @@ describe Discourse do
     it "correctly passes extra context" do
       exception = StandardError.new
 
-      Discourse.handle_exception(exception, {message: "Doing a test", post_id: 31}, nil)
+      Discourse.handle_job_exception(exception, {message: "Doing a test", post_id: 31}, nil)
       expect(logger.exception).to eq(exception)
       expect(logger.context.keys.sort).to eq([:current_db, :current_hostname, :message, :post_id].sort)
     end

spec/jobs/jobs_base_spec.rb

@@ -29,7 +29,7 @@ describe Jobs::Base do
   it 'handles errors in multisite' do
     RailsMultisite::ConnectionManagement.expects(:all_dbs).returns(['default','default','default'])
     # one exception per database
-    Discourse.expects(:handle_exception).times(3)
+    Discourse.expects(:handle_job_exception).times(3)
 
     bad = BadJob.new
     expect{bad.perform({})}.to raise_error

spec/jobs/poll_mailbox_spec.rb

@@ -34,7 +34,7 @@ describe Jobs::PollMailbox do
 
       Net::POP3.any_instance.expects(:start).raises(error)
 
-      Discourse.expects(:handle_exception)
+      Discourse.expects(:handle_job_exception)
 
       poller.poll_pop3
     end

spec/models/error_log_spec.rb

@@ -1,58 +0,0 @@
-require 'spec_helper'
-describe ErrorLog do
-
-  def boom
-    raise "boom"
-  end
-
-  def exception
-    begin
-      boom
-    rescue => e
-      return e
-    end
-  end
-
-  def controller
-    DraftController.new
-  end
-
-  def request
-    ActionController::TestRequest.new(host: 'test')
-  end
-
-  describe "add_row!" do
-    it "creates a non empty file on first call" do
-      ErrorLog.clear_all!
-      ErrorLog.add_row!(hello: "world")
-      expect(File.exists?(ErrorLog.filename)).to eq true
-    end
-  end
-
-  describe "logging data" do
-    it "is able to read the data it writes" do
-      ErrorLog.clear_all!
-      ErrorLog.report!(exception, controller, request, nil)
-      ErrorLog.report!(exception, controller, request, nil)
-      i = 0
-      ErrorLog.each do |h|
-        i += 1
-      end
-      expect(i).to eq 2
-    end
-
-    it "is able to skip rows" do
-      ErrorLog.clear_all!
-      ErrorLog.report!(exception, controller, request, nil)
-      ErrorLog.report!(exception, controller, request, nil)
-      ErrorLog.report!(exception, controller, request, nil)
-      ErrorLog.report!(exception, controller, request, nil)
-      i = 0
-      ErrorLog.skip(3) do |h|
-        i += 1
-      end
-      expect(i).to eq 1
-    end
-  end
-
-end