Background

My application code and libraries code call #silence method for logger instance.

For example, Sprockets calls it

sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb

module Sprockets
  module Rails
    class QuietAssets
      def initialize(app)
        @app = app
        @assets_regex = %r(\A/{0,2}#{::Rails.application.config.assets.prefix})
      end

      def call(env)
        if env['PATH_INFO'] =~ @assets_regex
          ::Rails.logger.silence { @app.call(env) }
        else
          @app.call(env)
        end
      end
    end
  end
end

Problem

Ougai doesn't have #silence method. so exception raised when #silence is called.
(of course the exception is not json... )

Question

1. @tilfin Do you have a plan about #silence method implementation?(extend?)
2. Is there have an idea about fixing the exception in application code

Links

• https://github.com/rails/rails/blob/master/activesupport/lib/active_support/logger_silence.rb

I run into the error of: Cannot load such file -- awesome_print when I use the Readable Formatter as specified in the wiki.
Gemfile: gem amazing_print
Gemfile.lock: amazing_print (1.2.1)

Trying to use ougai together with Rails. Ran into a problem with one of the default Rails logs from ActiveJob. When a job fails it logs something like "Error performing job" followed by a stack trace. This trace contains \n characters. This results in an ougai line such as:

{"name":"main", "msg":"Error performing job \n ..."}

Which is invalid JSON. Is ougai not guaranteed to output valid JSON?

Hi, I'm wondering why Ougai::Logger.new method does not support the :formatter option, which the parent ::Logger.new can accept.

For example:

logger = Ougai::Logger.new(STDOUT, formatter: Ougai::Formatters::Readable.new)
logger.formatter.class
#=> Ougai::Formatters::Bunyan

logger = ::Logger.new(STDOUT, formatter: Ougai::Formatters::Readable.new)
logger.formatter.class
#=> Ougai::Formatters::Readable

Ougai version is 1.8.0.

It would be great if you could give me any response.
Thank you.

Hi,

Is it possible to customize message key? For example, {"message": "hello"} instead of {"msg": "hello"}. We send log messages to google cloud stackdriver and it requires log messages to be formatted in the certain way to pretty print them in the console.

Thanks!

The awesome_print gem is no longer maintained.

A fork has been created that will continue maintaining the gem: amazing_print.

The dependency should move to amazing_print.

As of now, awesome print gives lots of warning with Ruby 2.7.0 such as (lots of), making ougai practically unusable:

/home/mic/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/awesome_print-1.8.0/lib/awesome_print/formatters/base_formatter.rb:113: warning: Capturing the given block using Proc.new is deprecated; use `&block` instead
/home/mic/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/awesome_print-1.8.0/lib/awesome_print/inspector.rb:63: warning: Capturing the given block using Proc.new is deprecated; use `&block` instead

I'm running into an issue, either with the colorize gem or with ougai...

When I set the ougai formatter to Ougai::Formatters::Readable, my colors turn dull.

My setup is tmux (with a custom tmux 256 termcap), iterm, and solarized dark on a mac, if that helps. Also, I'm using colorize 0.8.1 and ougai 1.9.1 and ruby 2.6.6.

normal

require 'colorize'
require 'ougai'
@logger = Ougai::Logger.new STDOUT
puts "red".red
puts "green".green

dull

require 'colorize'
require 'ougai'
@logger = Ougai::Logger.new STDOUT
@logger.formatter = Ougai::Formatters::Readable.new
puts "red".red
puts "green".green

The default Logger can accepts a progname with block syntax e.g. the following will set progname to initialize which is forwarded to the Logger::Formatter's call method:

logger.info('initialize') { "Initializing..." }

This does not seem to be supported by Ougai from what I can tell

Hello. I have some reason not to be able to use Oj, so is there a way to use another JSON library like the standard library JSON instead of Oj?

When I look into the code, it seems hard to replace Ougai::Serializer.for_json with some serializer without any monkey-patch.

If we could make Oj an optional dependency, it would be ideal for me.

I would appreciate it if you would consider it. Thanks.

I wanted to change log format from json to hash, and tried below

logger.formatter.jsonize = false
logger.formatter.with_newline = true

Unfortunately this will produce log without newline because as shown in code below, with_newline flag is ignored if jsonize is false

I'm happy to send PR to change behaviour but technically this will be breaking behaviour change so wanted to first open the issue.

Right now we are using Ougai for logging in production, now as it is using amazing_print one the dependency we are facing issue while loading Ougai::Formatters::Readable.new in production

Steps to reproduce

1. Add. Ougai as gem in Gemfile
2. Run bundle install
3. Start rails console -e production
4. Ougai::Formatters::Readable.new

Actual Result

LoadError: cannot load such file -- amazing_print
from /Users/sudeepaniltarlekar/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bootsnap-1.4.7/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `require'
Caused by Bootsnap::LoadPathCache::FallbackScan:

Expected Result

#<Ougai::Formatters::Readable:0x00007f8772dd1e30 ...>

Possible Solution
Right now amazing_print is under the test group in Gemfile, we should be moving that gem to the gemspec as a dependency

If this sounds good, will raise a PR

Thoughts?

Hey there - Ougai looks rad and I'm trying it out in a new project right now! Thanks for open-sourcing it.

One thing I noticed is that it doesn't support child loggers. It seems like you're familiar with bunyan for Node so I assume you know how they roll, but it really seems like something that might be nice to have (for example, I'm using it in a Grape API right now and I'd love my controllers to have their own logging tags)? If I get a chance I could take a crack at it, but either way I figured I'd drop a quick message to get the idea on your radar.

#with_logger is handy, but when you're going in and out of scopes, it's not quite so useful--I tend to think a new object probably makes some sense given how libraries often expect them.

I have a very simple LoggerBuilder class, main requirement for it is to:

• Output readable version of logs into STDOUT
• Output regular version to file

here is a code.

require 'ougai'

class LoggerBuilder
  attr_reader :logger

  def self.build(component_name)
    builder = new(component_name)
    builder.logger
  end

  def initialize(to_file)
    file_logger = Ougai::Logger.new(File.open("logs/#{to_file}.log", "a"))
    @logger = Ougai::Logger.new(STDOUT)
    @logger.formatter = Ougai::Formatters::Readable.new
    @logger.extend Ougai::Logger.broadcast(file_logger)
  end
end

in this scenario, logs will not be written to file. BUT if I'll comment out like with formatter

   #@logger.formatter = Ougai::Formatters::Readable.new

it works!

So, I'm not sure if this is a feature or a bug. But I decided to report to see what you think.

Thanks for an interesting project!

It would be nice if this gem would play nicely with jruby. I've noticed a recent dependency change from 'json' gem to 'oj' gem. It's a good change to do if your on MRI, oj is significantly faster. But it doesn't have any support for Jruby
https://github.com/ohler55/oj/blob/fca1a69c15d4f17b0401416f6376553d517483f9/pages/Compatibility.md

Are you willing to consider https://github.com/intridea/multi_json gem as an alternative? This way you'll be able to use oj and jruby guys will have a chance to try out this gem as well.

Not a critical thing, but I noticed that calls to loggers through ChildLogger are recursive. Might be worth having each ChildLogger record its parent and a fresh copy of all fields to reduce these; right now I've got four-level-deep child chains in places and while it isn't a performance concern yet, I can totally see it becoming an issue.

Because Ougai::ChildLogger does not subclass Ruby's stdlib Logger, I have run into issues when passing a "child" Ougai logger into a library which calls #add(...) on the passed logger.

A good example is in Bunny: https://github.com/ruby-amqp/bunny/blob/master/lib/bunny/transport.rb#L374

Here is a quick spec I prepared which illustrates the issue:

require 'json'
require 'ougai'

describe '#add should work' do
  let(:io) { StringIO.new }
  let(:logger) { Ougai::Logger.new(io) }

  it 'for normal loggers' do
    logger.add(Logger::INFO, 'foo')
    expect(JSON.parse(io.string)['msg']).to eq 'foo'
  end

  it 'for child loggers' do
    logger.child({ baz: 'qux' }).add(Logger::INFO, 'bar')
    JSON.parse(io.string).tap do |logged|
      expect(logged['msg']).to eq 'bar'
      expect(logged['baz']).to eq 'qux'
    end
  end
end

I think I have an idea for a clean fix if that would be helpful, but I wanted to see if this was intentional or not first.

Thanks very much! This is a great gem. 😃

How do we use this logger with rails and record request id with each log message?

I am seeing some weird behavior using Rails 5.2.2.1. I have followed the setup guide on the wiki and integrated it with lograge.

The message payload (which is a hash) is turned into a string. This is how it looks in the log:

{"name":"rails","hostname":"computer.local","pid":19340,"level":30,"time":1557826080140,"v":1,"msg":"{:msg=>\"Request\", :request=>{:method=>\"GET\", :path=>\"/products/card\", :format=>\"*/*\", :controller=>\"ProductsController\", :action=>\"card\", :status=>200, :duration=>713.12, :view=>223.27, :db=>135.91}, :request_id=>\"dade881f-4fc7-4171-a503-2937d33fe648\"}"}

I noticed that ActiveSupport::TaggedLogging is required by other gems (like webpacker and active job) and it extends the Rails.logger (which is now my custom Ougai logger). The tagged logger converts the message to a string in its call method:

def call(severity, timestamp, progname, msg) super(severity, timestamp, progname, "#{tags_text}#{msg}") end

Any idea why I am seeing this problem and how to avoid it?

I solved it for now by monkey patching the tagged logger module, but that doesn't feel like a long term solution.

When attempting to use, I get:

irb(main):001:0> require 'rubygems'
=> false
irb(main):002:0> require 'ougai'
=> true
irb(main):003:0> logger = Ougai::Logger.new(STDOUT)
=> #<Ougai::Logger:0x007fa34e1a76a8 @progname=nil, @level=0, @default_formatter=#<Logger::Formatter:0x007fa34e1a7630 @datetime_format=nil>, @formatter=#<Ougai::Formatters::Bunyan:0x007fa34e1a7540 @app_name="irb", @hostname="Jesse\xE2\x80\x99s-MacBook-Pro", @trace_indent=2, @trace_max_lines=100>, @logdev=#<Logger::LogDevice:0x007fa34e1a75e0 @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<IO:<STDOUT>>, @mon_owner=nil, @mon_count=0, @mon_mutex=#<Thread::Mutex:0x007fa34e1a7590>>, @default_message="No message", @exc_key=:err>
irb(main):005:0> logger.info('Information!')
Encoding::UndefinedConversionError: "\xE2" from ASCII-8BIT to UTF-8
	from /opt/rubies/2.3.3/lib/ruby/2.3.0/json/common.rb:224:in `encode'
	from /opt/rubies/2.3.3/lib/ruby/2.3.0/json/common.rb:224:in `generate'
	from /opt/rubies/2.3.3/lib/ruby/2.3.0/json/common.rb:224:in `generate'
	from /Users/jessemcginnis/.gem/ruby/2.3.3/gems/ougai-0.7.3/lib/ougai/formatters/bunyan.rb:8:in `call'
	from /opt/rubies/2.3.3/lib/ruby/2.3.0/logger.rb:546:in `format_message'
	from /opt/rubies/2.3.3/lib/ruby/2.3.0/logger.rb:434:in `add'
	from /opt/rubies/2.3.3/lib/ruby/2.3.0/logger.rb:489:in `info'
	from /Users/jessemcginnis/.gem/ruby/2.3.3/gems/ougai-0.7.3/lib/ougai/logger.rb:20:in `info'
	from (irb):5
	from /opt/rubies/2.3.3/bin/irb:11:in `<main>'

Hi there, thanks for taking the time to read this.

I'm looking at putting structured logging into our rails apps and Ougai seems to give me what I'm looking for. I was wondering what people think about being able to turn off certain properties/fields that are logged by default.

Consider the following example, where the name, hostname, pid, level, time and 'v' attributes are included in the log messages.

{"name":"rails","hostname":"sample-app","pid":7,"level":30,"time":1527602643707,"v":1,"foo":"bar","message":"Generated in new_model."}
{"name":"rails","hostname":"sample-app","pid":7,"level":30,"time":1527602643808,"v":1,"method":"GET","path":"/","format":"html","controller":"NewController","action":"new","status":200,"duration":123.81,"view":8.01,"params":{}}

In my use case, these fields are not useful or desirable and they end up cluttering the logs. The output I'd like is similar to this, with the aforementioned fields removed:

{"@timestamp":"2018-05-29T15:03:50.516+01:00","foo":"bar","message":"Generated in new_model."}
{"@timestamp":"2018-05-29T15:03:50.641+01:00","method":"GET","path":"/","format":"html","controller":"NewController","action":"new","status":200,"duration":147.87,"view":19.29,"params":{}}

To achieve this, I've used a custom formatter which does not pass those fields to dump. I've also combined ougai with lograge.

What I was wanting to discuss is an additional config item, something like this:

config.logger.default_fields = [:pid]

The way I envisage this working is that if the config isn't set, then the default fields would be as normal, i.e. [:name, :hostname, :pid, :level, :time, :v]. However, this setting could be overridden to exclude some of the default fields that the various formatters apply. This could perhaps be achieved by using a new formatter and possibly this setting then controlled at the point of initialization.

I'm open to ideas and suggestions and I am thinking of contributing with a PR, so would happily take suggestions for that too.

Hi,

I'm trying to use our custom logger (which inherits from Ougai::Logger) with Sidekiq 7, but am running into trouble. The instructions in the wiki work great for our other app, which is still on Sidekiq 6.

Our logger essentially is:

module Chargefox
  class Logger < Ougai::Logger
    include ActiveSupport::LoggerThreadSafeLevel
    include ActiveSupport::LoggerSilence

    attr_reader :formatter    

    def create_formatter
      Chargefox::StructuredLogFormatter.new
    end
  end
end

In the sidekiq config block:

Sidekiq.configure_server do |config|
    config.logger = Rails.logger.child({'service.namespace' => 'sidekiq'})
    ap "Logger class: #{config.logger.class.name}"
    ap "has method: #{config.logger.respond_to?(:formatter)}"
end

"Logger class: "
"has method: false"
undefined method `formatter' for #<#<Class:0x000000012f9819f0>:0x000000011eaaefc8 @before_log=nil, @level=nil, @parent=#<Chargefox::Logger:0x0000000129ada780 @level=1, @progname=nil, @default_formatter=#<Logger::Formatter:0x0000000129adab18 @datetime_format=nil>, @formatter=#<Chargefox::StructuredLogFormatter:0x0000000129ada758 @app_name="sidekiq", @hostname="ams-mac-020.local", @trace_indent=2, @trace_max_lines=100, @serialize_backtrace=true, @datetime_format="%FT%T.%3N%:z">, @logdev=#<Logger::LogDevice:0x0000000129adaa28 @shift_period_suffix=nil, @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<IO:<STDOUT>>, @binmode=false, @mon_data=#<Monitor:0x0000000129ada9d8>, @mon_data_owner_object_id=9480>, @before_log=nil, @default_message="No message", @exc_key=:err, @with_fields={}>, @with_fields={"service.namespace"=>"sidekiq"}>
/Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/sidekiq-7.1.6/lib/sidekiq/cli.rb:44:in `run'
/Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/sidekiq-7.1.6/bin/sidekiq:31:in `<top (required)>'

Should .child return an instance of Chargefox::Logger in this case?

Additionally, If I pass a fresh instance of our logger to Sidekiq, e.g.

config.logger = Chargefox::Logger.new($stdout)

Something else goes pretty wrong and we get a stack overflow:

{"timestamp":1700098610796550000,"utc_time":"2023-11-16T01:36:50Z","service.name":"local-chargefox-core","service.version":"local","service.namespace":"web","severity_text":"DEBUG","message":"Server Middleware: Sidekiq::Failures::Middleware, Sidekiq::Metrics::Middleware, Rollbar::Sidekiq::ResetScope, Sidekiq::Status::ServerMiddleware"}
{"timestamp":1700098610796581000,"utc_time":"2023-11-16T01:36:50Z","service.name":"local-chargefox-core","service.version":"local","service.namespace":"web","severity_text":"INFO","message":"Starting processing, hit Ctrl-C to stop"}
bundler: failed to load command: sidekiq (/Users/joff/.rbenv/versions/3.0.6/bin/sidekiq)
/Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:107:in `binary': stack level too deep (SystemStackError)
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:109:in `visit_CAT'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:103:in `visit'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:162:in `visit'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:117:in `unary'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:119:in `visit_GROUP'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:103:in `visit'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:162:in `visit'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:107:in `binary'
	 ... 11348 levels...
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/bundler-2.4.21/lib/bundler/friendly_errors.rb:117:in `with_friendly_errors'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/bundler-2.4.21/exe/bundle:29:in `<top (required)>'
	from /Users/joff/src/chargefox/ocpp-messages/bin/bundle:118:in `load'
	from /Users/joff/src/chargefox/ocpp-messages/bin/bundle:118:in `<main>'

I expect something breaking has changed here, and we won't be able to drop in our own logger class, and instead will need to supply a formatter for the default Sidekiq:Logger instead? If that is the case, it might be nice to update the wiki :)

The Wiki page on Use as Rails logger shows that your custom logger needs to override initialize and call after_initialize.
That method is deprecated and removed in more recent versions of Rails, and is not necessary to call it anymore:

Logger don't need to call #after_initialize directly anymore. It will be deprecated without replacement in Rails 6.1.

I wanted to add this to the Wiki page to save some time for future developers, but I don't have write access to the Wiki, so I'm opening an issue instead 😄

AFAIU, child logger can only add fields to its parent logger, according to some logic.
However, when it comes to the child logger's level, it is purely inherited from the parent logger.
Is there a way to set the child logger's level, too?
If not, maybe there is a way to clone a logger and set a different log level to the cloned object?

It worked now after reboot, sorry for confusing.

From WiKi, if add ap gem, will pretty print log into stdout, but, i tried several times, no luck.

Following is test code.

1. Gemfile

gem 'awesome_print'
gem 'ougai', github: 'tilfin/ougai', branch: 'master'

2. test code.

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

3. output log.

Started GET "/posts/" for 127.0.0.1 at 2019-08-30 00:54:52 +0800
Processing by PostsController#index as HTML
  Rendering posts/index.html.erb within layouts/application
  Rendered posts/index.html.erb within layouts/application (32.8ms)
Completed 200 OK in 259ms (Views: 235.2ms | ActiveRecord: 3.4ms)


Started GET "/posts/" for 127.0.0.1 at 2019-08-30 00:54:58 +0800
Processing by PostsController#index as HTML
  Rendering posts/index.html.erb within layouts/application
  Rendered posts/index.html.erb within layouts/application (3.4ms)
Completed 200 OK in 52ms (Views: 50.2ms | ActiveRecord: 0.4ms)

i never see logs like this:

Hello! Thank you for the awesome work you are doing.
Recently, I have encountered some issues when tried to do redaction. I have implemented it in following way:

logger.before_log = lambda do |data|
  redact_sensitive(data)
end

def redact_sensitive(data)
  data.each do |key, value|
    if value.is_a?(Hash)
      redact_sensitive(value)
    elsif value.is_a?(String) && sensitive?(key)
      data[key] = "**REDACTED**"
    end
  end
end

def sensitive?(key)
 filter_parameters.include?(key.to_s)
end

This is working well but has one unfortunate sideeffect - it mutates the hash passed to log. Ougai does not take the defensive copy and if user will pass actual application data it can result in it being mutated.

Maybe, I am using the wrong place to implement the logic or am missing something. Would really appreciate you pointing me in right direction.

As lograge does:

Rails.application.configure do
  config.lograge.keep_original_rails_log = true

  config.lograge.logger = ActiveSupport::Logger.new "#{Rails.root}/log/lograge_#{Rails.env}.log"
end

Hi,

We've noticed the JSON logger doesn't conform to the standard syslog severity values:

• Here's ougai implementation:

  ougai/lib/ougai/formatters/for_json.rb

  Line 18 in d3f1412

  def to_level(severity)

• Here are the standard levels for the different severity values according to syslog: https://en.wikipedia.org/wiki/Syslog#Severity_level which happen to be the same ones as Ruby Logger class uses.

Is that intentional? And if so what is the reasoning behind it? Would you consider changing these values to be the standard syslog values?

Thanks

For a child logger, it can be useful to have a specified prefix string added to all logs.

From the README, but using .child():

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)

# start a child logger

child_logger = logger.child(child: true)

loggechild_loggerr.info('Hello!')

child_logger.error('Failed to do something.')

child_logger.level = Logger::WARN # error_logger level is also set WARN by propagation
child_logger.warn('Ignored something.')

Stdout output

{"name":"test","hostname":"karl-pietrzaks-mbp.local","pid":73910,"level":30,"time":"2022-08-18T15:56:24.014-04:00","v":0,"msg":"Hello!","child":true}
{"name":"test","hostname":"karl-pietrzaks-mbp.local","pid":73910,"level":50,"time":"2022-08-18T15:56:24.014-04:00","v":0,"msg":"Failed to do something.","child":true}
{"name":"test","hostname":"karl-pietrzaks-mbp.local","pid":73910,"level":40,"time":"2022-08-18T15:56:24.015-04:00","v":0,"msg":"Ignored something.","child":true}

error.log

# Logfile created on 2022-08-18 15:56:08 -0400 by logger.rb/66358

Is this intentional? I assumed creating a child logger would broadcast as well. Thoughts?

Use Case

I have a central setup_logging.rb file that sets up multiple loggers, and then:

1. each module require's setup_logging
2. sets up a child logger for itself

Hi, I noticed the weird behavior about development logging on Ougai and Rails integration with Readable formatter.

The PoC is here:
https://github.com/ybiquitous/ougai-rails-example/pull/1

I referred to the Wiki page for setup.

Even if development logging is enabled as follow,

# config/environments/development.rb
Rails.application.configure do
  config.logger = YourApp::Logger.new(config.paths["log"].first)
end

The log/development.log outputs empty messages as follow:

The behavior does not occur on log/test.log. 🤔

I would be happy if you could see the behavior.
Thanks.

logger.rb:26:in `_call'
logger.rb:15:in `call'
gems/activesupport-5.1.6.1/lib/active_support/tagged_logging.rb:21:in `call'
ruby/2.5.0/logger.rb:584:in `format_message'

so print

{:msg=>"{:msg=> 'message'}"}

I am looking to achieve something similar to what is possible with ActiveSupport::TaggedLogging:

logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
logger.tagged('BCX') { logger.info 'Stuff' }                            # Logs "[BCX] Stuff"
logger.tagged('BCX', "Jason") { logger.info 'Stuff' }                   # Logs "[BCX] [Jason] Stuff"
logger.tagged('BCX') { logger.tagged('Jason') { logger.info 'Stuff' } } # Logs "[BCX] [Jason] Stuff"

The important thing to note here is that the logger is mutated for the duration of the block execution - there is no "child logger" yielded to the block. This is useful because it is often difficult/impossible to inject the child logger into code called within the block. For example, many libraries only allow a logger to be provided once, on initialization.

A real-world use case would be to tag all logs produced while servicing a request with the request ID.

I could be missing something, but I don't see a nice way of doing this using Ougai. Is this something you would be interested in supporting?

So far, the best I have come up with is this:

def with_log_fields(fields)
  previous_fields = logger.with_fields
  logger.with_fields = previous_fields.merge(fields)
  yield
ensure
  logger.with_fields = previous_fields
end

with_log_fields({request_id: request.id}) { logger.info("Something happened") }

I am hoping for something more like this to be supported out of the box:

logger.with_fields({request_id: request.id}) { logger.info "Something happened" }

The current behavior is that level represented as number 10...60. What we need is literal: debug, info, error. How can we change the output of the level?

I have the following config for my tests:

config.lograge.enabled = true
console_logger = Ougai::Logger.new(STDOUT)
console_logger.level = Logger::ERROR

# Assign Ougai logger
config.logger = console_logger

And my output still has warn & info outputs such as:

{"name":"rspec","hostname":"localhost.localdomain","pid":42514,"level":30,"time":"2019-12-14T12:48:36.574+01:00","v":0,"msg":"Added roles 'executive' to user xxxx"}

Where I can see that the level field seems ok.

What am I missing?

Might be a good idea to allow specification of the time zone Ougai should be using for its logs, at least as an arg for the JSON formatters. In production we run servers as UTC, but for obvious reasons my dev workstation doesn't. ;)

Similar to #112, it seems the child logger doesn't implement <<.

I'm running into an issue where I turned on http_wire_trace in the AWS Ruby SDK, which logs the wire trace in the net gem via <<:

https://github.com/ruby/net-http/blob/master/lib/net/http.rb#L2475

This is something I've been looking at, but figuring out a good way to hook Ougai into Rack's logging for request logging seems like something that'd be pretty handy. Maybe somebody else has already done the heavy lifting here?

Hi! I've recently become more interested in structured logging, and have looked into a few structured logging libraries.

You get amazing power when you dump the logs from all of your different systems and sources into a centralized log store, and can then view and analyze them as one whole.

What I've noticed though is that the various structured logging frameworks all save JSON log entries in similar, but slightly different schemas.

For example, for storing timestamps, this library uses the JSON key "time", while other libraries use "timestamp" or "at". Another area where libraries differ is in how they store log levels.

These small differences cause friction when analyzing the central logstore, which contains structured logs that have been collected from multiple systems/microservices.

For example, one service might tag warnings with the string "WARN" while another with the string "warning". So if I want to view only warnings, I need to take this difference into account and write a tricky "OR" filter expression. This may seem minor, but these small inconsistencies cause great pain.

I believe that these small differences between the various structured logging libraries exist not because of any strongly held opinions, but simply because mainstream structured and centralized logging is still relatively young, and so there is no standard or common consensus.

I think it would be very beneficial to everyone if we could all unite around a common format.

To get things started, I have created a GitHub repository to centralize discussions here: https://github.com/bitc/structured-logging-schema

It contains a comparison between several structured logging libraries, summarizing the differences between them all. This can hopefully be a start to help us arrive at common ground.

I encourage the authors of this library (and anyone else who has an opinion) to participate in the discussion!

Discussion takes place in the issues for this repo: https://github.com/bitc/structured-logging-schema

This is most likely a stupid question but I cannot figure out what the intended purpose of the "v" key is in the log output?

It is always 0 for me and looking through the code I see it is sometimes 0 or 1 in the tests.

Could you shed some light on what this key is for? 😄

Hi,

I'm updating my Ougai version from (1.8.2 to 1.8.5 or 2.0.0), I have Ougai in my Gemfile. Trying to load my application it breaks complaining that amazing_print isn't available. We added awesome_print to our Gemfile back in the days to make ougai work. Now we are adding amazing_print to solve the issue again.

My class looks like:

class FooReadable < Ougai::Formatters::Readable
 ...
 end

I see that in your gemspec you require amazing_print just in the test group.. isn't that a problem? Shouldn't it be loaded in all groups?

In Sidekiq 6.0 you can't access Sidekiq::Logging.logger anymore. You can now set config.logger directly and access the logger through Sidekiq.logger

Sidekiq.configure_server do |config|
  # logging with sidekiq context
  config.logger = Rails.logger.child
  config.logger.before_log = lambda do |data|
    ctx = Thread.current[:sidekiq_context]
    break unless ctx
    items = ctx.map {|c| c.split(' ') }.flatten
    data[:sidekiq_context] = items if items.any?
  end
  # Replace default error handler
  config.error_handlers.pop
  config.error_handlers << lambda do |ex, ctx|
    Sidekiq.logger.warn(ex, job: ctx[:job]) # except job_str
  end
end

How would we make ougai inherit from mono logger as to protect against trapped threads.

Hi! I am getting this warning a lot of times while running RSpec:

/Users/alebian/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/ougai-1.7.0/lib/ougai/logger.rb:71: warning: instance variable @before_log not initialized

When I try to print the below log, it prints "level" in numbers. Instead, I want it in the log level name itself.
logger.info('Information!') {"name":"main","hostname":"mint","pid":14607,"level":30,"time":"2016-10-16T22:26:48.835+09:00","v":0,"msg":"Information!"}

Am expecting,

logger.info('Information!') {"name":"main","hostname":"mint","pid":14607,"level":"Info","time":"2016-10-16T22:26:48.835+09:00","v":0,"msg":"Information!"}
How to do this?

Hello and thanks for this nice gem! I have a very strange issue. One application. During local running everything is okay. But when I run it on the demo env I see broken log structure:

{"name":"rackup","hostname":"4a37fsdf352a47","pid":9,"level":30,"time":"2023-09-22T14:26:36.298+00:00","v":0,"msg":"{:msg=>\"No message\", :service_name=>\"my-service\", :service_version=>\"1.0.0\", :team=>\"my-team\", :trace_id=>\"d0e7a1f58c8ffbb50a2655b465e76e77\", :span_id=>\"f05a320ca0b6aa96\"}"}

Under msg key we can see collected, not serialized as json, context, that should be in the root of expected json. Any ideas?

Seems this issue is very similar to: #94

When using ougai as my logger and initializing honeybadger, I'm unable to start a rails console, on a fresh rails-5.1.4 install, with ruby-2.3.1.

1. rails new rtest -d postgresql
2. cd rtest
3. copy files into place
4. bundle install
5. bundle exec rails s
   • should succeed
6. bundle exec rails c
   • should fail
7. Comment out logger line, in application.rb
8. bundle exec rails c
   • should succeed

Stacktrace of failure

/app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/ougai-1.5.7/lib/ougai/formatters/readable.rb:22:in `delete': no implicit conversion of Symbol into String (TypeError)
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/ougai-1.5.7/lib/ougai/formatters/readable.rb:22:in `call'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/logger.rb:546:in `format_message'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/logger.rb:434:in `add'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/honeybadger-3.2.0/lib/honeybadger/logging.rb:100:in `add'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/honeybadger-3.2.0/lib/honeybadger/logging.rb:134:in `add'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/honeybadger-3.2.0/lib/honeybadger/logging.rb:49:in `block (2 levels) in <class:Base>'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/honeybadger-3.2.0/lib/honeybadger/config.rb:58:in `init!'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/honeybadger-3.2.0/lib/honeybadger/init/rails.rb:21:in `block in <class:Railtie>'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:67:in `block in execute_hook'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:60:in `with_execution_control'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:65:in `execute_hook'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:50:in `block in run_load_hooks'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:49:in `each'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:49:in `run_load_hooks'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/application/finisher.rb:73:in `block in <module:Finisher>'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/initializable.rb:30:in `instance_exec'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/initializable.rb:30:in `run'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/initializable.rb:59:in `block in run_initializers'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/tsort.rb:228:in `block in tsort_each'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/tsort.rb:431:in `each_strongly_connected_component_from'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/tsort.rb:349:in `block in each_strongly_connected_component'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/tsort.rb:347:in `each'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/tsort.rb:347:in `call'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/tsort.rb:347:in `each_strongly_connected_component'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/tsort.rb:226:in `tsort_each'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/tsort.rb:205:in `tsort_each'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/initializable.rb:58:in `run_initializers'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/application.rb:353:in `initialize!'
        from /app/devel/rtest2/config/environment.rb:5:in `<top (required)>'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/dependencies.rb:292:in `require'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/dependencies.rb:292:in `block in require'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/dependencies.rb:258:in `load_dependency'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/dependencies.rb:292:in `require'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/spring-2.0.2/lib/spring/application.rb:102:in `preload'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/spring-2.0.2/lib/spring/application.rb:153:in `serve'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/spring-2.0.2/lib/spring/application.rb:141:in `block in run'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/spring-2.0.2/lib/spring/application.rb:135:in `loop'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/spring-2.0.2/lib/spring/application.rb:135:in `run'
        from /app/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/spring-2.0.2/lib/spring/application/boot.rb:19:in `<top (required)>'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:55:in `require'
        from /app/.rbenv/versions/2.3.1/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:55:in `require'
        from -e:1:in `<main>'

Gemfile

source 'https://rubygems.org'


gem 'rails', '~> 5.1.4'
gem 'pg', '~> 0.20'
gem 'sass-rails', '~> 5.0'
gem 'uglifier', '>= 1.3.0'
gem 'coffee-rails', '~> 4.2.2'

gem 'jquery-rails'
gem 'turbolinks'
gem 'jbuilder', '~> 2.0'
gem 'sdoc', '~> 0.4.0', group: :doc
gem 'honeybadger'
gem 'ougai'
gem 'awesome_print'
gem 'google-api-client', require: 'google/apis/sheets_v4'
gem 'restforce'
gem 'omniauth-salesforce'
gem 'salesforce_bulk_api'

gem 'puma'
gem 'redis-session-store'

group :development, :test do
  gem 'byebug'
  gem 'rspec-rails'
  gem 'faker'
  gem 'activerecord-nulldb-adapter'
end

group :development do
  gem 'web-console'
  gem 'listen', '>= 3.0.5', '< 3.2'

  gem 'spring'
  gem 'spring-watcher-listen', '~> 2.0.0'
end

config/application.rb

require_relative 'boot'

require 'rails/all'
require_relative '../lib/ld_api/logger'

# Require the gems listed in Gemfile, including any gems
# you've limited to :test, :development, or :production.
Bundler.require(*Rails.groups)

module Rtest2
  class Application < Rails::Application
    # Initialize configuration defaults for originally generated Rails version.
    config.load_defaults 5.1

    # Settings in config/environments/* take precedence over those specified here.
    # Application configuration should go into files in config/initializers
    # -- all .rb files in that directory are automatically loaded.
    config.autoload_paths << Rails.root.join('lib')
    config.colorize_logging = false
    config.logger = LdApi::Logger.new(STDOUT)
  end
end

lib/ld_api/logger.rb

require 'ougai'

module LdApi
  class Logger < Ougai::Logger
    include ActiveSupport::LoggerThreadSafeLevel
    include LoggerSilence

    def initialize(*args)
      super
      after_initialize if respond_to? :after_initialize
    end

    def create_formatter
      if Rails.env.development? || Rails.env.test?
        Ougai::Formatters::Readable.new
      else
        Ougai::Formatters::Bunyan.new
      end
    end
  end
end

config/honeybadger.yml

---
api_key: somekey

As suggested in the wiki, we're including ActiveSupport::LoggerSilence in our logger like so

module OurRailsApp
  class Logger < Ougai::Logger
    include ActiveSupport::LoggerSilence
  end
end

However this is broken in 1.9.0 because of the changes in #113.

Including the ActiveSupport::LoggerSilence also includes ActiveSupport::LoggerThreadSafeLevel, which overrides #add and reverts it to the original signature (here).

We then get an ArgumentError when we try to log anything:

ArgumentError: wrong number of arguments (given 4, expected 1..3)
gems/activesupport-6.1.1/lib/active_support/logger_thread_safe_level.rb:59:in `add'
gems/ougai-1.9.0/lib/ougai/logging.rb:42:in `debug'

Hi!

First of all, thanks for a great gem.

Following code

logger = Ougai::Logger.new(STDOUT)
logger.with_fields = { app: 'myapp' }

request_logger = logger.child(request_id: "dh17gd816gfub")
request_logger.info("completed", ms: 12345, status: 200)

Produces

{"name":"rails_console","hostname":"...","pid":...,"level":30,"time":"...","v":0,"msg":"completed","ms":12345,"status":200,"request_id":"dh17gd816gfub","app":"myapp"}

But I expect something like this

{"name":"rails_console","hostname":"...","pid":...,"level":30,"time":"...","msg":"completed","app":"myapp","request_id":"dh17gd816gfub","ms":12345,"status":200,"v":0}

I know that JSON object structure natively is not ordered. But it looks logical to me to preserve fields order when consecutively adding them with with_fields and child. It's also much more convenient for human readability of the logs, when more "generic" fields come before more specific.

Such libraries as pino for nodejs and zerolog for golang keep fields ordered.

I haven't check yet, but it even looks like a regression here, so should be quite easy to fix.

Thank you.