Simple Activity Logging in Ruby

Activity Logs are one of the most requested (and consequently, most under-used) features in an application. Managers love the idea of having a full history of everyone’s activity, even though their startup will probably pivot before they have a chance to look at these logs. Jokes apart though, the data in the activity logs are tremendous sources of business value which can help you iterate ever closer to your users requirements. So, it kind of helps to have handy a nice pattern to simplify the creation of activity logs.

The whole problem with activity logging is that it straddles the Controller and Model layers. The activity is being performed on a model, but the model has no knowledge of who is performing the activity. This knowledge is the preserve of the Controller. There have been many approaches to solve this problem. Some of them include setting global environment variables (ouch! not thread safe), using cattr_accessor and hacking around with threads and so on, or perhaps this approach recommended in http://rails-bestpractices.com/posts/47-fetch-current-user-in-models which includes thread local variables.

The other layer of complexity of course arises from the question of how to actually do the logging. Who should do it? When should it be done? Traditionally, approaches have centered around before/after callbacks in the model i.e Doing a before_save :get_attributes to get the original state of the object and then a after_save :log to write the activity log. We all know what the problems are with before and after hooks - they add behaviour to the model which is orthogonal to the models main concern which is persistence. Also, such hooks need to stubbed out while testing, etc. Also, adding hooks means we do not have any control over when stuff gets logged and when it doesn’t. If tomorrow we want to create a secret backdoor for the NSA to silently change data behind people’s backs, we can’t do that without changing the model, which means that a concern with logging is causing the class that deals with persistence to change - Holy SRP Violation, Batman!

If you’ve been in this situation, then I can say, fear no more - there’s a very simple way of solving this problem. Here goes - consider the following situation

# following are extracts from the relevant classes and not real Ruby code.
class Foo
belongs_to :user
end
class User
has n, :foos
end
class Staff
end
view raw foo.rb hosted with ❤ by GitHub

We have Users, who can have Foos and also there are Staffs who do data entry as well and can modify Foos that belong to other users. In our ActivityLog, we want to persist the following stuff

class ActivityLog
include DataMapper::Resource
property :id, Serial
property :type, Discriminator
property :model_id, Integer
property :event, String
property :diff, JSON
property :user_id, Integer
property :staff_id, Integer
end
view raw activity_log.rb hosted with ❤ by GitHub

Now, here’s the absurdly simple solution. Are you ready? Ok. In your controller, instead of calling @foo.save, say @foo.save_with_log(current_user). Got it? Ok, I’ll say it again.

class FoosController < ActionController::Base
# ..snip ..
def create
@foo = Foo.new(params[:foo])
@foo.save_with_log(current_user)
# ...
end
end

Simple? We need the model to know about a user? Pass it in as a parameter!

Now, what about the model side? As much as we hate mixins as a form of inheritance/delegation, logging is one of those cases where mixins are a good approach (I’m willing to be convinced to the contrary though). This is behaviour that is shared across all classes that need logging and it actually has nothing to do with the behaviour of the class itself, so we’ll make a nice little module called ActivityLogger which looks like this. Please note, this is pseudo code (it hasn’t been tested)

module ActivityLogger
include ActiveSupport
def self.included(base)
base.extend ClassMethods
end
module ClassMethods
def log_with(model_name, options = {})
@@activity_logger_options = {
:save_method => :save_with_log,
:update_method => :update_with_log,
:validate_method => :valid?,
:exclude_attributes => []
}.merge(options)
@@activity_logger = model_name.to_s.camelize.constantize
end
def activity_logger
@@activity_logger
end
def activity_logger_options
@@activity_logger_options
end
end
def save_with_log(doer, options = {})
self.class.activity_logger.send(self.class.activity_logger_options[:save_method], self, doer, self.class.activity_logger_options.merge(options))
end
def update_with_log(attributes,doer,options = {})
self.class.activity_logger.send(self.class.activity_logger_options[:update_method], self, attributes, doer, self.class.activity_logger_options.merge(options))
end
end

and we update our model thus

class Foo
include DataMapper::Resource
include ActivityLogger
log_with :foo_activity_log
# ...snip ...
end
view raw foos.rb hosted with ❤ by GitHub

The log_with :foo_activity_log is important. What we’ve done in the save_with_log and update_with_log methods that we included from ActivityLogger, is to inject a dependency on the appropriate class that will do the actual logging for us, in this case FooActivityLog. In order to save (or update) and log, we need the objects attributes, a handle to the user/staff who is performing the action and alongside these, we can pass any other data in a hash which the actual logger can use as it deems fit. To achieve all this, what the ActivityLog module does is to translate a call to @foo.save_with_log(staff) into a call to FooActivityLog.save_with_log(@foo, staff, options). So, what does the actual logger look like? Something like this

class ActivityLog
include DataMapper::Resource
property :id, Serial
property :type, Discriminator
property :model_id, Integer
property :event, String
property :diff, JSON
property :user_id, Integer
property :staff_id, Integer
def self.save_with_log(object, saver, options, &blk)
if object.save
diff = object.attributes.reject{|k,v| options[:exclude_attributes]}
create( :event => "save",
:model_id => object.id,
:diff => diff,
:staff_id => saver.id if saver.class == Staff,
:user_id => object.user ? object.user.id : nil
)
else
return false
end
end
def self.update_with_log(object, attrs, saver, options, &blk)
orig_attrs = object.attributes
if object.update(attrs)
diff = orig_attrs.log_diff(object.attributes).reject{|k,v| options[:exclude_attributes].include?(k)}
create(:event => "update",
:model_id => object.id,
:diff => diff,
:staff_id => saver.id if saver.class == Staff,
:user_id => object.user ? object.user.id : nil)
end
end
end
class FooActivityLog < ActivityLog
end
view raw activity_log.rb hosted with ❤ by GitHub

Several advantages to this approach which accrue from favouring the explicit over the implicit.

  • We have two implicit methods now, save_with_log and update_with_log, so we don’t need to mess with before and after callbacks.
  • The actual activity log model inherits from ActivityLog, so we can override behaviour as we wish. For example, while saving nested models we might want to call save_with_log on the nested model as well. For such situations, we can easily implement methods as we deem fit in the appropriate child class of ActivityLog
  • We are injecting controller variables explicitly, such as the current user or staff member performing the action. This saves us from having to mess with thread local variables. It also makes it super easy to test this functionality.

So, in short, being explicit about all our dependencies gives us a tonne of advantages over other approaches that depend on magic or callbacks.

What do you think?