Merge pull request #25 from tilfin/feature/logger-before_log

Implement before_log attribute on logging

README.md

@@ -214,6 +214,28 @@ gc_logger.debug('something detail', age: 34, weight: 72)
 
 If any field exists in both parent log and child log, the parent value is overridden or merged by child value.
 
+### Hook before logging
+
+Setting `before_log` of logger or child an *lambda* with `data` field, a process can be run before log each output.
+
+* Adding variable data (like Thread ID) to logging data can be defined in common.
+* Returning `false` in *lambda*, the log is cancelled and does not output.
+* The *before_log* of child logger is run ahead of the parent logger's.
+
+```ruby
+logger.before_log = lambda do |data|
+  data[:thread_id] = Thread.current.object_id.to_s(36)
+end
+
+logger.debug('on main thread')
+Thread.new { logger.debug('on another thread') }
+```
+
+```json
+{"name":"main","hostname":"mint","pid":13975,"level":20,"time":"2017-08-06T15:35:53.435+09:00","v":0,"msg":"on main thread","thread_id":"gqe0ava6c"}
+{"name":"main","hostname":"mint","pid":13975,"level":20,"time":"2017-08-06T15:35:53.435+09:00","v":0,"msg":"on another thread","thread_id":"gqe0cb14g"}
+```
+
 ## View log by node-bunyan
 
 Install [bunyan](https://github.com/trentm/node-bunyan) via NPM

lib/ougai/child_logger.rb

@@ -11,14 +11,16 @@ def level
       @parent.level
     end
 
-    def chain(severity, args, fields)
-      @parent.chain(severity, args, merge_fields(@with_fields, fields))
+    def chain(severity, args, fields, hooks)
+      hooks.push(@before_log) if @before_log
+      @parent.chain(severity, args, merge_fields(@with_fields, fields), hooks)
     end
 
     protected
 
     def append(severity, args)
-      @parent.chain(severity, args, @with_fields)
+      hooks = @before_log ? [@before_log] : []
+      @parent.chain(severity, args, @with_fields, hooks)
     end
   end
 end

lib/ougai/logger.rb

@@ -25,22 +25,28 @@ def self.broadcast(logger)
       end
     end
 
-    def chain(severity, args, fields)
-      write(severity, args, merge_fields(@with_fields, fields))
+    def chain(severity, args, fields, hooks)
+      hooks.push(@before_log) if @before_log
+      write(severity, args, merge_fields(@with_fields, fields), hooks)
     end
 
     protected
 
     def append(severity, args)
-      write(severity, args, @with_fields)
+      hooks = @before_log ? [@before_log] : []
+      write(severity, args, @with_fields, hooks)
     end
 
     def create_formatter
       Formatters::Bunyan.new
     end
 
-    def write(severity, args, fields)
-      add(severity, merge_fields(fields, to_item(args)))
+    def write(severity, args, fields, hooks)
+      data = merge_fields(fields, to_item(args))
+      hooks.each do |hook|
+        return false if hook.call(data) == false
+      end
+      add(severity, data)
     end
 
     def to_item(args)

lib/ougai/logging.rb

@@ -1,6 +1,7 @@
 module Ougai
   module Logging
     attr_accessor :with_fields
+    attr_writer :before_log
 
     def debug(message = nil, ex = nil, data = nil, &block)
       return true if level > Logger::DEBUG
@@ -41,7 +42,7 @@ def child(fields = {})
       ChildLogger.new(self, fields)
     end
 
-    def chain(severity, args, fields)
+    def chain(_severity, _args, _fields, _hooks)
       raise NotImplementedError
     end
 

lib/ougai/version.rb

@@ -1,3 +1,3 @@
 module Ougai
-  VERSION = "1.2.0"
+  VERSION = "1.3.0"
 end

spec/child_logger_spec.rb

@@ -297,4 +297,60 @@
       end
     end
   end
+
+  describe '#before_log' do
+    let(:logger) { parent_logger.child }
+    let(:log_msg) { 'before_log test' }
+
+    before do
+      parent_logger.level = Logger::INFO
+    end
+
+    context 'child logger to be set before_log' do
+      before do
+        logger.before_log = lambda do |data|
+          data[:context_id] = 123
+        end
+      end
+
+      it 'outputs the field to be added in before_log' do
+        logger.info(log_msg)
+        expect(item).to be_log_message(log_msg, 30)
+        expect(item).to include(context_id: 123)
+      end
+    end
+
+    context 'parent logger to be set before_log' do
+      before do
+        parent_logger.before_log = lambda do |data|
+          data[:context_id] = 12345
+        end
+      end
+
+      it 'outputs the field to be added in before_log' do
+        logger.info(log_msg)
+        expect(item).to be_log_message(log_msg, 30)
+        expect(item).to include(context_id: 12345)
+      end
+    end
+
+    context 'both child logger and parent logger to be set before_log' do
+      before do
+        logger.before_log = lambda do |data|
+          data[:context_id] = 67890
+          data[:context_name] = 'sub'
+        end
+        parent_logger.before_log = lambda do |data|
+          data[:context_id] = 12345
+        end
+      end
+
+      it 'outputs the fields to be added in each before_log' do
+        logger.info(log_msg)
+        expect(item).to be_log_message(log_msg, 30)
+        expect(item).to include(context_id: 12345) # parent
+        expect(item).to include(context_name: 'sub') # child
+      end
+    end
+  end
 end

spec/logger_spec.rb

@@ -483,4 +483,37 @@
       end
     end
   end
+
+  describe '#before_log' do
+    let(:log_msg) { 'before_log test' }
+
+    context 'set context data' do
+      before do
+        logger.level = Logger::INFO
+        logger.before_log = lambda do |data|
+          data[:context_id] = 123
+        end
+      end
+
+      it 'outputs with context data' do
+        logger.info(log_msg)
+        expect(item).to be_log_message(log_msg, 30)
+        expect(item).to include(context_id: 123)
+      end
+    end
+
+    context 'cancelling log' do
+      before do
+        logger.level = Logger::INFO
+        logger.before_log = lambda do |data|
+          false
+        end
+      end
+
+      it 'outputs none' do
+        logger.info(log_msg)
+        expect(item).to be_nil
+      end
+    end
+  end
 end