Additive configuration is problematic - suggest overriding instead

[seddy]

In reevoo-sapience, we have the following configuration:

default:
  log_level: debug
  appenders:
    - datadog:
        url: <%= ENV.fetch("STATSD_URL", "udp://localhost:8125") %>
    - stream:
        io: STDOUT
        formatter: json

development:
  log_level: debug
  appenders:
    - datadog:
        url: <%= ENV.fetch("STATSD_URL", "udp://localhost:8125") %>
    - stream:
        io: STDOUT
        formatter: color
    - stream:
        file_name: log/development.log
        formatter: color

The problem is that the stream configurations are additive. So in the development environment we end up logging two streams to STDOUT: one using color and the other using json. This makes development very difficult to read and unnecessarily verbose.

I propose when we have a stream in development it overrides all streams from above it, to allow for greater flexibility in configuration. Arguably the same should go for all appenders; I wonder whether we're logging twice to datadog?

[mhenrixon]

It isn't additive. Any key under the environment replaces the one in the parent.

[seddy]

That's not what I see locally in Filler on master, which is up to date on reevoo_sapience-rb. I see two streams of output for everything to STDOUT, one color and one json. There are no overrides in config/sapience.yml in Filler for development either....

[mhenrixon]

Most probably then it gets initialized oddly :) If you try Sapience.configure(force: true) in filler does that fix your problem?

[seddy]

Nope :(

Specifically look a the double log line for SELECT * FROM reviews when calling Review.first

15:56:09@~/src/reevoo/filler (master):> be rails c
warning: parser/current is loading parser/ruby21, which recognizes
warning: 2.1.7-compliant syntax, but you are running 2.1.8.
2016-12-14 15:56:43.135504 D [69593:70205967842240 log_subscriber.rb:93] Rails --    (0.3ms)  SELECT `retailers`.`id` FROM `retailers` WHERE `retailers`.`trkref` = 'MAZ'
2016-12-14 15:56:43.138575 D [69593:70205967842240 log_subscriber.rb:93] Rails --    (0.3ms)  SELECT `retailers`.`id` FROM `retailers` WHERE `retailers`.`trkref` = 'MAZ'
2016-12-14 15:56:43.139283 D [69593:70205967842240 log_subscriber.rb:93] Rails --    (0.2ms)  SELECT `retailers`.`id` FROM `retailers` WHERE `retailers`.`trkref` = 'MAZ'
2016-12-14 15:56:43.153545 I [69593:70205967842240 logger.rb:23] Rails -- sentry -- ** [Raven] Raven 2.0.2 configured not to capture errors.
Loading development environment (Rails 4.2.5.1)

[1] pry(main)> Review.first
2016-12-14 15:56:43.365039 D [69593:70205967842240 log_subscriber.rb:93] Rails --   Review Load (1.1ms)  SELECT  `reviews`.* FROM `reviews`  ORDER BY `reviews`.`id` ASC LIMIT 1
2016-12-14 15:56:43.365342 D [69593:70205967842240 log_subscriber.rb:93] (1.320ms) Sapience::Extensions::ActiveRecord::LogSubscriber -- { :sql => "SELECT `reviews`.* FROM `reviews` ORDER BY `reviews`.`id` ASC LIMIT 1", :name => "Review Load", :connection_id => 70206037427540, :statement_name => nil, :binds => [], :tags => [ "request" ] }
=> nil


[2] pry(main)> Sapience.configure(force: true)
=> #<Sapience::Configuration:0x007fb433a82c28
 @ap_options={:multiline=>false},
 @app_name=nil,
 @appenders=[{:stream=>{:io=>"STDOUT", :formatter=>"color"}}, {:stream=>{:file_name=>"log/development.log", :formatter=>"color"}}],
 @backtrace_level=:debug,
 @backtrace_level_index=1,
 @default_level=:debug,
 @default_level_index=1,
 @error_handler={:silent=>{}},
 @filter_parameters=["password", "password_confirmation"],
 @host=nil,
 @log_executor=:single_thread_executor,
 @metrics={:datadog=>{}},
 @options=
  {:log_level=>"debug",
   :host=>nil,
   :ap_options=>{:multiline=>false},
   :appenders=>[{:stream=>{:io=>"STDOUT", :formatter=>"color"}}, {:stream=>{:file_name=>"log/development.log", :formatter=>"color"}}],
   :log_executor=>:single_thread_executor,
   :metrics=>{:datadog=>{}},
   :error_handler=>{:silent=>{}},
   :filter_parameters=>["password", "password_confirmation"]}>


[3] pry(main)> Review.first
2016-12-14 15:56:56.642329 D [69593:70205967842240 log_subscriber.rb:93] Rails --   Review Load (0.3ms)  SELECT  `reviews`.* FROM `reviews`  ORDER BY `reviews`.`id` ASC LIMIT 1
2016-12-14 15:56:56.642674 D [69593:70205967842240 log_subscriber.rb:93] (0.570ms) Sapience::Extensions::ActiveRecord::LogSubscriber -- { :sql => "SELECT `reviews`.* FROM `reviews` ORDER BY `reviews`.`id` ASC LIMIT 1", :name => "Review Load", :connection_id => 70206037427540, :statement_name => nil, :binds => [], :tags => [ "request" ] }
=> nil

[seddy]

Although interestingly, the configured appenders in that log output is actually showing a color one to STDOUT!!! Maybe this is something else?