Permalink
Browse files

Add better logging

  • Loading branch information...
1 parent a3bc082 commit 817fa4a12ffcaf04ea3029fb1cf80a7de1736d75 @rwdaigle committed Mar 19, 2012
View
@@ -1,2 +1,2 @@
web: bundle exec unicorn -p $PORT -c ./config/unicorn.rb
-queue: bundle exec rake queue:work
+queue: bundle exec rake jobs:work
@@ -45,6 +45,7 @@ def update_question
end
def queue
+ logger.info "[UnitsController] event=queue subject_id=#{parent_object.id} subject=\"#{parent_object}\""
$queue.enqueue('Subject.process!', parent_object.id)
flash[:notice] = "#{parent_object} has been queued for processing of empty units."
redirect_to parent_object
@@ -5,18 +5,12 @@ class WordnikProcessor
class << self
def process!(subject, unit)
- logger.info "[Processor] event=start processor=#{self.to_s} subject_id=#{subject.id} subject=\"#{subject.title}\" unit_id=#{unit.id} question=\"#{unit.question}\""
result = answer = nil
- ms = Benchmark.ms do
+ log(subject, unit, "answer=\"#{answer}\"") do
result = Wordnik.word.get_definitions(unit.question, :limit => 1)
answer = result && !result.empty? ? result[0]['text'] : nil
unit.update_attributes(answer: answer)
end
- logger.info "[Processor] event=end processor=#{self.to_s} subject_id=#{subject.id} subject=\"#{subject.title}\" unit_id=#{unit.id} question=\"#{unit.question}\" answer=\"#{answer}\" execution=#{ms}ms"
- end
-
- def logger
- ActiveRecord::Base.logger
end
end
end
View
@@ -17,8 +17,10 @@ def seedRandom(seed)
end
def process!(subject_id, overwrite=false)
- subject = self.find(subject_id)
- subject.process!(overwrite) if subject
+ log("subject_id=#{subject_id}", "overwrite=#{overwrite}") do
+ subject = self.find(subject_id)
+ subject.process!(overwrite) if subject
+ end
end
end
@@ -41,14 +43,16 @@ def to_param; permalink; end
# Use name as to_s
def to_s; title; end
+ def to_log; "subject_id=#{self.id} subject=\"#{self}\""; end
+
private
def resolve_processor_class
if(unit_processor_type)
begin
@resolved_processor_class ||= "#{unit_processor_type}_processor".classify.constantize
rescue
- logger.error "[Subject] event=error message=\"Unable to resolve processor class '#{unit_processor_type}' #{$!}\""
+ log("status=error", self, "message=\"Unable to resolve processor class '#{unit_processor_type}' #{$!}\"", "error=#{$!}")
end
end
end
View
@@ -9,8 +9,6 @@ class Unit < ActiveRecord::Base
has_many :learnings, :dependent => :delete_all
has_many :reviews, :dependent => :delete_all
has_many :associations, :dependent => :delete_all
-
- after_create :enqueue_for_processing
acts_as_list :scope => :subject
@@ -54,16 +52,14 @@ def <=>(other)
end
def process!(overwrite = false)
- if answer.blank? || overwrite
- subject.with_processor do |processor_klass|
- processor_klass.process!(self, unit)
+ log(subject, self, "overwrite=#{overwrite}") do
+ if answer.blank? || overwrite
+ subject.with_processor do |processor_klass|
+ processor_klass.process!(self, unit)
+ end
end
end
end
- def enqueue_for_processing
- if answer.blank?
- $queue.enqueue('Unit.process!', self.id)
- end
- end
+ def to_log; "unit_id=#{self.id} unit=\"#{question}\""; end
end
@@ -0,0 +1,8 @@
+class UnitObserver < ActiveRecord::Observer
+
+ observe :unit
+
+ def after_create(unit)
+ log(unit) { $queue.enqueue('Unit.process!', unit.id) }
+ end
+end
View
@@ -24,6 +24,7 @@ class Application < Rails::Application
# Activate observers that should always be running.
# config.active_record.observers = :cacher, :garbage_collector, :forum_observer
+ config.active_record.observers = :unit_observer
# Set Time.zone default to the specified zone and make Active Record auto-convert to this zone.
# Run "rake -D time" for a list of tasks for finding time zone names. Default is UTC.
@@ -0,0 +1 @@
+require 'event_logging'
View
@@ -0,0 +1,53 @@
+require 'active_support/concern'
+
+module EventLogger
+
+ extend ActiveSupport::Concern
+
+ module ClassMethods
+
+ def hiya; puts "hiya"; end
+
+ def log(*tokens, &block)
+ ms = Benchmark.ms { yield } if block_given?
+ token_str = tokens.collect do |token|
+ token.respond_to?(:to_log) ? token.to_log : token.to_s
+ end.join(' ')
+ execution = ms ? "execution=#{ms.round(3)}ms" : nil
+ klass = self.is_a?(Class) ? self : self.class
+ event_logger.info "[#{klass}] event=#{self.caller_method} #{token_str} #{execution}"
+ end
+
+ def caller_method(depth=1)
+ parse_caller(caller(depth+1).first).last
+ end
+
+ def event_logger
+ ActiveRecord::Base.logger
+ end
+
+ # Stolen from ActionMailer, where this was used but was not made reusable
+ def parse_caller(at)
+ if /^(.+?):(\d+)(?::in `(.*)')?/ =~ at
+ file = Regexp.last_match[1]
+ line = Regexp.last_match[2].to_i
+ method = Regexp.last_match[3]
+ [file, line, method]
+ end
+ end
+ end
+
+ def log(*tokens, &block)
+ ms = Benchmark.ms { yield } if block_given?
+ token_str = tokens.collect do |token|
+ token.respond_to?(:to_log) ? token.to_log : token.to_s
+ end.join(' ')
+ execution = ms ? "execution=#{ms.round(3)}ms" : nil
+ klass = self.is_a?(Class) ? self : self.class
+ self.class.event_logger.info "[#{klass}] event=#{self.class.caller_method} #{token_str} #{execution}"
+ end
+end
+
+class Object
+ include EventLogger
+end

0 comments on commit 817fa4a

Please sign in to comment.