log all exceptions during check or receive to Agents' logs

app/models/agent.rb

@@ -144,6 +144,10 @@ class Agent < ActiveRecord::Base
     AgentLog.log_for_agent(self, message, options)
   end
 
+  def error(message, options = {})
+    log(message, options.merge(:level => 4))
+  end
+
   # Class Methods
   class << self
     def cannot_be_scheduled!
@@ -201,9 +205,14 @@ class Agent < ActiveRecord::Base
     # and Event ids instead of a literal ActiveRecord models because it is preferable to serialize delayed_jobs with ids.
     def async_receive(agent_id, event_ids)
       agent = Agent.find(agent_id)
-      agent.receive(Event.where(:id => event_ids))
-      agent.last_receive_at = Time.now
-      agent.save!
+      begin
+        agent.receive(Event.where(:id => event_ids))
+        agent.last_receive_at = Time.now
+        agent.save!
+      rescue => e
+        agent.error "Exception during receive: #{e.message} -- #{e.backtrace}"
+        raise
+      end
     end
     handle_asynchronously :async_receive
 
@@ -228,9 +237,14 @@ class Agent < ActiveRecord::Base
     # id instead of a literal Agent because it is preferable to serialize delayed_jobs with ids.
     def async_check(agent_id)
       agent = Agent.find(agent_id)
-      agent.check
-      agent.last_check_at = Time.now
-      agent.save!
+      begin
+        agent.check
+        agent.last_check_at = Time.now
+        agent.save!
+      rescue => e
+        agent.error "Exception during check: #{e.message} -- #{e.backtrace}"
+        raise
+      end
     end
     handle_asynchronously :async_check
   end

app/models/agents/website_agent.rb

@@ -69,7 +69,7 @@ module Agents
       log "Fetching #{options[:url]}"
       request = Typhoeus::Request.new(options[:url], :followlocation => true)
       request.on_failure do |response|
-        log "Failed: #{response.inspect}"
+        error "Failed: #{response.inspect}"
       end
       request.on_success do |response|
         doc = parse(response.body)
@@ -84,7 +84,7 @@ module Agents
                        elsif extraction_details[:text]
                          node.text()
                        else
-                         log ":attr or :text is required on HTML or XML extraction patterns"
+                         error ":attr or :text is required on HTML or XML extraction patterns"
                          return
                        end
                      }
@@ -95,7 +95,7 @@ module Agents
         num_unique_lengths = options[:extract].keys.map { |name| output[name].length }.uniq
 
         if num_unique_lengths.length != 1
-          log "Got an uneven number of matches for #{options[:name]}: #{options[:extract].inspect}", :level => 4
+          error "Got an uneven number of matches for #{options[:name]}: #{options[:extract].inspect}"
           return
         end
 

spec/models/agent_spec.rb

@@ -125,25 +125,40 @@ describe Agent do
     end
 
     describe ".async_check" do
-      it "records last_check_at and calls check on the given Agent" do
-        checker = Agents::SomethingSource.new(:name => "something")
-        checker.user = users(:bob)
-        checker.save!
+      before do
+        @checker = Agents::SomethingSource.new(:name => "something")
+        @checker.user = users(:bob)
+        @checker.save!
+      end
 
-        mock(checker).check.once {
-          checker.options[:new] = true
+      it "records last_check_at and calls check on the given Agent" do
+        mock(@checker).check.once {
+          @checker.options[:new] = true
         }
 
-        mock(Agent).find(checker.id) { checker }
+        mock(Agent).find(@checker.id) { @checker }
+
+        @checker.last_check_at.should be_nil
+        Agents::SomethingSource.async_check(@checker.id)
+        @checker.reload.last_check_at.should be_within(2).of(Time.now)
+        @checker.reload.options[:new].should be_true # Show that we save options
+      end
 
-        checker.last_check_at.should be_nil
-        Agents::SomethingSource.async_check(checker.id)
-        checker.reload.last_check_at.should be_within(2).of(Time.now)
-        checker.reload.options[:new].should be_true # Show that we save options
+      it "should log exceptions" do
+        mock(@checker).check.once {
+          raise "foo"
+        }
+        mock(Agent).find(@checker.id) { @checker }
+        lambda {
+          Agents::SomethingSource.async_check(@checker.id)
+        }.should raise_error
+        log = @checker.logs.first
+        log.message.should =~ /Exception/
+        log.level.should == 4
       end
     end
 
-    describe ".receive!" do
+    describe ".receive! and .async_receive" do
       before do
         stub_request(:any, /wunderground/).to_return(:body => File.read(Rails.root.join("spec/data_fixtures/weather.json")), :status => 200)
         stub.any_instance_of(Agents::WeatherAgent).is_tomorrow?(anything) { true }
@@ -155,6 +170,19 @@ describe Agent do
         Agent.receive!
       end
 
+      it "should log exceptions" do
+        mock.any_instance_of(Agents::TriggerAgent).receive(anything).once {
+          raise "foo"
+        }
+        Agent.async_check(agents(:bob_weather_agent).id)
+        lambda {
+          Agent.receive!
+        }.should raise_error
+        log = agents(:bob_rain_notifier_agent).logs.first
+        log.message.should =~ /Exception/
+        log.level.should == 4
+      end
+
       it "should track when events have been seen and not received them again" do
         mock.any_instance_of(Agents::TriggerAgent).receive(anything).once
         Agent.async_check(agents(:bob_weather_agent).id)