My friend, who is just learning Ruby, asked how he can automatically wrap some code around each user defined method in a class. The requirement (from his bosses) is to log when each method is being called.
To be more concrete, we want to factor out lines 3, 5, 9 and 11 from the following snippet.
1 class AutoLogger
2 def method_a
3 puts "start logging method_a"
4 puts "calling method_a"
5 puts "end logging method_a"
6 end
7
8 def method_b
9 puts "start logging method_b"
10 puts "calling method_b"
11 puts "end logging method_b"
12 end
13 end
The problem really boils down to two problems. First, how to redefine a method to be the original method body wrapped between the logging code. Second, how do we specify which methods in a class should be wrapped.
Each solution (except for the first one) relies on using Module#define_method to redefine the method in question. Sometimes we pass in a block that defines the original method, other times we make an UnboundMethod out of the original method and call it from the block that makes the new method body, binding it to self which at execution time is an instance of our class.
My friend said ideally, he wants every "user defined" method to automatically be wrapped.
The first solution I came up with was using method_missing. This solution has the drawback of having to refactor all your code to call log_some_method instead of some_method.
1 class AutoLogger
2
3 def method_missing(name, *args)
4 name = name.to_s
5 if name[0,4] == 'log_'
6 method_name = name[4..-1]
7 puts "start logging #{method_name}"
8 self.send(method_name.to_sym, *args)
9 puts "end logging #{method_name}"
10 else
11 super
12 end
13 end
14
15 def method_a
16 puts "calling method_a"
17 end
18
19 def method_b(arg1, arg2)
20 puts "calling method_b(#{arg1}, #{arg2})"
21 end
22
23 end
24
25 o = AutoLogger.new
26 o.method_a
27 o.method_b("test", 1)
28 o.log_method_a
29 o.log_method_b("test", 1)
30
31 32 33 34 35 36 37 38 39 40 41
With this approach, you can see that the original methods are kept intact and are callable. You have to call the special prefixed version of them to get the logging.
The next solution uses a special method to define methods instead of the def keyword.
1 class AutoLogger
2
3 def self.def_with_logging(method_name, &block)
4 define_method(method_name) do |*args|
5 puts "start logging #{method_name}"
6 yield *args
7 puts "end logging #{method_name}"
8 end
9 end
10
11 def_with_logging(:method_a) do
12 puts "calling method_a"
13 end
14
15 def_with_logging(:method_b) do |arg1, arg2|
16 puts "calling method_b(#{arg1}, #{arg2})"
17 end
18
19 end
20
21 o = AutoLogger.new
22 o.method_a
23 o.method_b("test", 1)
24
25 26 27 28 29 30 31 32 33
Again, this solution requires the programmer to refactor a lot of existing code (rewriting all your methods using def_with_logging instead of def).
The third solution is more "Rails-like" by adding a method to the class itself which can be called to add logging to existing methods.
1 class AutoLogger
2 @@inited = false
3
4 def self.do_logging_for(*method_names)
5 @@method_names ||= []
6 @@method_names += method_names
7 end
8
9 do_logging_for :method_a, :method_b
10
11 def initialize
12 unless @@inited
13 @@method_names.each do |method_name|
14 self.class.class_eval do
15 method = instance_method(method_name)
16 define_method(method_name) do |*args|
17 puts "start logging #{method_name}"
18 method.bind(self).call(*args)
19 puts "end logging #{method_name}"
20 end
21 end
22 end
23 @@inited = true
24 end
25 end
26
27 def method_a
28 puts "calling method_a"
29 end
30
31 def method_b(arg1, arg2)
32 puts "calling method_b(#{arg1}, #{arg2})"
33 end
34
35 end
36
37 o = AutoLogger.new
38 o.method_a
39 o.method_b("test", 1)
40
41 42 43 44 45 46 47 48 49
Notice how most of the work is deferred to initialize. This is so we can call do_logging_for before we define the methods it works on.
The fourth approach takes the least work because it does not require the programmer to do anything special or extra to get the desired effect. It all happens automatically.
1 class AutoLogger
2
3 def self.method_added(method_name)
4
5 6 @@seen_methods ||= {}
7 return if @@seen_methods.has_key?(method_name)
8 @@seen_methods[method_name] = true
9
10 method = instance_method(method_name)
11 define_method(method_name) do |*args|
12 puts "start logging #{method_name}"
13 method.bind(self).call(*args)
14 puts "end logging #{method_name}"
15 end
16 end
17
18 def method_a
19 puts "calling method_a"
20 end
21
22 def method_b(arg1, arg2)
23 puts "calling method_b(#{arg1}, #{arg2})"
24 end
25
26 end
27
28 o = AutoLogger.new
29 o.method_a
30 o.method_b("test", 1)
31
32 33 34 35 36 37 38 39 40
Class#method_added is a callback that gets fired, well, when you think it does. The interesting thing to note here is that we can go into infinite recursion because of how we redefinite each method. When a method is a defined the callback is triggered, in the callback we redefine the method which causes the callback to be triggered again.
That's it. Pretty neat what you can do with Ruby, huh?
