A Ruby structured logging is capable of handling a message, custom data or an exception easily and generates JSON or human readable logs.
Clone or download
Latest commit 7464290 Dec 8, 2018
Permalink
Type Name Latest commit message Commit time
Failed to load latest commit information.
lib Bump 1.7.1 Nov 30, 2018
spec Fix warning unused variable Nov 30, 2018
.gitignore Implement coverage Jul 1, 2017
.rspec warning is on Nov 30, 2018
.travis.yml Bump Ruby 2.6 RC1 Dec 8, 2018
Gemfile Fix pino time is epoch msec Feb 18, 2018
LICENSE.txt First commit Oct 16, 2016
README.md Add awesome ougai link Nov 30, 2018
Rakefile Fix parsing formatter initialize arguments Feb 15, 2018
ougai.gemspec Change bundler version Dec 8, 2018

README.md

Ougai

Gem Version document Build Status Code Climate Test Coverage

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 Awesome 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 pass through itself to ::Logger.

require 'rubygems'
require 'ougai'

logger = Ougai::Logger.new(STDOUT)

TRACE level

The level of logger supports TRACE level lower than DEBUG.

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 field, msg is set default_message attribute value of a Logger. its default is 'No 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 `<main>'"}}

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 `<main>'"}}

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 `<main>'"}}

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

loggger.fatal { ex }

loggger.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 add to all logs as is.

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 with_fields is specified in each log, the field is overridden. But if the field's type is Array, both with_field value and logging value are merged with concat and uniq.

Create a child logger

logger.child(with_fields) creates a child logger of self. Its argument with_fields add to all logs the child logger outputs. A child logger can also create its child logger. If you pass a block to this method, the child logger will be yielded to it.

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
{"name":"main","hostname":"mint2","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":"mint2","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":"mint2","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":"mint2","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":"mint2","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."}

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.
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 can be used to like ActiveSupport::Logger.broadcast.

An example

Original logger outputs STDOUT and error_logger outputs ./error.log. Every calling for logger is propagated to error_logger.

logger = Ougai::Logger.new(STDOUT)

error_logger = Ougai::Logger.new('./error.log')
logger.extend Ougai::Logger.broadcast(error_logger)

logger.level = Logger::INFO
logger.info('Hello!')

error_logger.level = Logger::ERROR
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 `<main>'
[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 `<main>'

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

Use human Readable formatter for console

Add awesome_print to Gemfile and bundle

gem 'awesome_print'

Set Ougai::Formatters::Readable instance to formatter accessor

require 'rubygems'
require 'ougai'

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

Screen result example

Screen Shot

How to use with famous products, services and libraries

Custom formatters and integrations

License

MIT