Ougai

A structured logging system is capable of handling a message, structured data or an exception easily. It has JSON formatters compatible with Bunyan or pino for Node.js and human readable formatter with Amazing Print for console.

Installation

Add this line to your application's Gemfile:

gem 'ougai'

And then execute:

$ bundle

Or install it yourself as:

$ gem install ougai

Usage

Ougai::Logger is sub-class of original Logger in Ruby. All arguments of the

initialize

require 'rubygems'
require 'ougai'

logger = Ougai::Logger.new(STDOUT)

TRACE level

The

level

logger.level = Ougai::Logger::TRACE # , :trace or 'trace'

log only a message

logger.info('Information!')

{"name":"main","hostname":"mint","pid":14607,"level":30,"time":"2016-10-16T22:26:48.835+09:00","v":0,"msg":"Information!"}

log only structured data

logger.info({
  msg: 'Request', method: 'GET', path: '/login',
  format: 'html', controller: 'LoginController',
  action: 'new', status: 200
})
logger.debug(user: { name: 'Taro', age: 19 })

{"name":"main","hostname":"mint","pid":9044,"level":30,"time":"2016-10-28T17:58:53.668+09:00","v":0,"msg":"Request","method":"GET","path":"/login","format":"html","controller":"LoginController","action":"new","status":200}
{"name":"main","hostname":"mint","pid":9044,"level":20,"time":"2016-10-28T17:58:53.668+09:00","v":0,"msg":"No message","user":{"name":"Taro","age":19}}

If a data does not contain

msg

default_message

logger.default_message = 'User dump'
logger.debug(user: { name: 'Taro', age: 19 })

{"name":"main","hostname":"mint","pid":9303,"level":20,"time":"2016-10-28T18:03:50.118+09:00","v":0,"msg":"User dump","user":{"name":"Taro","age":19}}

log only an exception

begin
  raise StandardError, 'some error'
rescue => ex
  logger.error(ex)
end

{"name":"main","hostname":"mint","pid":4422,"level":50,"time":"2016-10-22T13:05:02.989+09:00","v":0,"msg":"some error","err":{"name":"StandardError","message":"some error","stack":"main.rb:24:in `
'"}}

log with a message and custom data

logger.debug('Debugging', data_id: 1, data_flag: true)
logger.debug('Debug!', custom_data: { id: 1, name: 'something' })

{"name":"main","hostname":"mint","pid":14607,"level":20,"time":"2016-10-16T22:26:48.836+09:00","v":0,"msg":"Debugging","data_id":1,"data_flag":true}
{"name":"main","hostname":"mint","pid":14607,"level":20,"time":"2016-10-16T22:26:48.836+09:00","v":0,"msg":"Debug!","custom_data":{"id":1,"name":"something"}}

log with a message and an exception

begin
  raise StandardError, 'fatal error'
rescue => ex
  logger.fatal('Unexpected!', ex)
end

{"name":"main","hostname":"mint","pid":14607,"level":60,"time":"2016-10-16T22:26:48.836+09:00","v":0,"msg":"Unexpected!","err":{"name":"StandardError","message":"fatal error","stack":"main.rb:12:in `
'"}}

log with an exception and custom data

begin
  raise StandardError, 'some error'
rescue => ex
  logger.error(ex, error_id: 999)
end

{"name":"main","hostname":"mint","pid":13962,"level":50,"time":"2016-10-28T23:44:52.144+09:00","v":0,"error_id":999,"err":{"name":"StandardError","message":"some error","stack":"main.rb:40:in `
'"}}

log with a message, an exception and custom data

begin
  1 / 0
rescue => ex
  logger.error('Caught error', ex, reason: 'zero spec')
end

{"name":"main","hostname":"mint","pid":14607,"level":50,"time":"2016-10-16T22:26:48.836+09:00","v":0,"msg":"Caught error","err":{"name":"ZeroDivisionError","message":"divided by 0","stack":"main.rb:18:in `/'\n ...'"},"reason":"zero spec"}

logs with blocks

logger.info { 'Hello!' }

logger.debug do
  ['User dump', { name: 'Taro', age: 15 }]
end
logger.error do
  ['Failed to fetch info', ex, { id: 10 }]
end
logger.fatal { ex }
logger.fatal do
  ['Unexpected', ex]
end

To specify more than one of a message, an exception and custom data, the block returns them as an array.

Adding custom fields to all logs

The fields of

with_fields

logger.with_fields = { version: '1.1.0' }
logger.debug(user: { name: 'Taro', age: 19 })
logger.info('Hello!', user: { name: 'Jiro' }, version: '2.3')

{"name":"test","hostname":"mint","pid":30182,"level":20,"time":"2017-07-22T20:52:12.332+09:00","v":0,"version":"1.1.0","msg":"No message","user":{"name":"Taro","age":19}}
{"name":"test","hostname":"mint","pid":30308,"level":30,"time":"2017-07-22T20:53:54.314+09:00","v":0,"version":"2.3","user":{"name":"Jiro"},"msg":"Hello!"}

If any field of withfields is specified in each log, the field is overridden. If the field's type is Array, both withfield value and logging value are merged with

concat

uniq

If the field's type is Hash, then values are merged recursively.

logger.with_fields = { version: '1.1.0', user: { name: 'Taro' } }
logger.debug(user: { age: 19 })

{"name":"test","hostname":"mint","pid":30182,"level":20,"time":"2017-07-22T20:52:12.332+09:00","v":0,"version":"1.1.0","msg":"No message","user":{"name":"Taro","age":19}}

Create a child logger

logger.child(with_fields)

with_fields

logger = Ougai::Logger.new(STDOUT)
logger.with_fields = { app: 'yourapp', tags: ['service'], kind: 'main' }

child_logger = logger.child({ tags: ['user'], kind: 'logic' })
logger.info('Created child logger')
child_logger.info('Created a user', name: 'Mike')
gc_logger = child_logger.child({ kind: 'detail' })
child_logger.info('Created grand child logger')
gc_logger.debug('something detail', age: 34, weight: 72)
gc_logger.child({ mode: 'processed' }) do |gcc_logger|
  gcc_logger.info('Great-grandchild logger that will be cleaned up on block exit.')
  :some_return_value
end
child_logger.sev_threshold = :error # alias of level
child_logger.info('This is not outputted')
gc_logger.info('This is not outputted')
child_logger.error('This is outputted')
gc_logger.error('This is outputted')
child_logger.level = :debug # does not work because the level is below parent one
child_logger.debug('This is not outputted')

{"name":"main","hostname":"mint","pid":8342,"level":30,"time":"2017-08-01T22:07:20.400+09:00","v":0,"app":"yourapp","tags":["service"],"kind":"main","msg":"Created child logger"}
{"name":"Mike","hostname":"mint","pid":8342,"level":30,"time":"2017-08-01T22:07:20.400+09:00","v":0,"app":"yourapp","tags":["service","user"],"kind":"logic","msg":"Created a user"}
{"name":"main","hostname":"mint","pid":8342,"level":30,"time":"2017-08-01T22:07:20.400+09:00","v":0,"app":"yourapp","tags":["service","user"],"kind":"logic","msg":"Created grand child logger"}
{"name":"main","hostname":"mint","pid":8342,"level":20,"time":"2017-08-01T22:07:20.400+09:00","v":0,"app":"yourapp","tags":["service","user"],"kind":"detail","age":34,"weight":72,"msg":"something detail"}
{"name":"main","hostname":"mint","pid":8342,"level":20,"time":"2017-08-01T22:07:20.400+09:00","v":0,"app":"yourapp","tags":["service","user"],"kind":"detail","mode":"processed","msg":"Great-grandchild logger that will be cleaned up on block exit."}
{"name":"main","hostname":"mint","pid":4894,"level":50,"time":"2017-08-01T22:07:20.401+09:00","v":0,"app":"yourapp","tags":["service","user"],"kind":"logic","msg":"This is outputed"}
{"name":"main","hostname":"mint","pid":4894,"level":50,"time":"2017-08-01T22:07:20.401+09:00","v":0,"app":"yourapp","tags":["service","user"],"kind":"detail","msg":"This is outputed"}

If any field exists in both parent log and child log, the parent value is overridden or merged by child value.

If the field's type is Hash, then values are merged recursively.

Hook before logging

Setting

before_log

data

• 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.

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') }

{"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"}

Using broadcast, log output plural targets

Ougai::Logger.broadcast

ActiveSupport::Logger.broadcast

An example

Original

logger

error_logger

./error.log

logger

error_logger

logger = Ougai::Logger.new(STDOUT)
logger.level = Logger::INFO

error_logger = Ougai::Logger.new('./error.log')
error_logger.level = Logger::ERROR
logger.extend Ougai::Logger.broadcast(error_logger)
logger.info('Hello!')
logger.error('Failed to do something.')
logger.level = Logger::WARN # error_logger level is also set WARN by propagation
logger.warn('Ignored something.')

STDOUT

{"name":"main","hostname":"mint","pid":24915,"level":30,"time":"2017-08-16T17:23:42.415+09:00","v":0,"msg":"Hello!"}
{"name":"main","hostname":"mint","pid":24915,"level":50,"time":"2017-08-16T17:23:42.416+09:00","v":0,"msg":"Failed to do something."}
{"name":"main","hostname":"mint","pid":24915,"level":40,"time":"2017-08-16T17:23:42.416+09:00","v":0,"msg":"Ignored something."}

error.log

{"name":"main","hostname":"mint","pid":24915,"level":50,"time":"2017-08-16T17:23:42.415+09:00","v":0,"msg":"Failed to do something."}
{"name":"main","hostname":"mint","pid":24915,"level":40,"time":"2017-08-16T17:23:42.416+09:00","v":0,"msg":"Ignored something."}

View pretty logs with node-bunyan or pino

Install bunyan or pino via npm

$ npm install -g bunyan

Pipe a log file to command

$ cat output.log | bunyan
[2016-10-16T22:26:48.835+09:00]  INFO: main/14607 on mint: Info message!
[2016-10-16T22:26:48.836+09:00] DEBUG: main/14607 on mint: Debugging (data_id=1, data_flag=true)
[2016-10-16T22:26:48.836+09:00] DEBUG: main/14607 on mint: Debug!
    custom_data: {
      "id": 1,
      "name": "something"
    }
[2016-10-16T22:26:48.836+09:00] FATAL: main/14607 on mint: Unexpected!
    main.rb:12:in `
'
[2016-10-16T22:26:48.836+09:00] ERROR: main/14607 on mint: Caught error (reason="z
    main.rb:18:in `/'
      main.rb:18:in `
'

If you use Ougai::Formatters::Pino, you can use command pino as well as bunyan.

Use human Readable formatter for console

Add amazing_print to Gemfile and

bundle

gem 'amazing_print'

Set Ougai::Formatters::Readable instance to

formatter

require 'rubygems'
require 'ougai'

logger = Ougai::Logger.new(STDOUT)
logger.formatter = Ougai::Formatters::Readable.new

Screen result example

How to use with famous products, services and libraries

• Use as Rails logger and apply the request with Lograge
• Customize Sidekiq logger
• Forward logs to Fluentd
• Forward logs to Logentries
• Use as ServerEngine logger
• Forward logs to Loggly
• Use as Rack logger

Custom formatters and integrations

• Awesome Ougai

License

MIT