Duplicate logging to STDOUT when using rails server

[eprothro]

The documentation states that if add_file_appender is set to false no logs will go anywhere. The implication being that a configuration like

config.rails_semantic_logger.add_file_appender = false
config.semantic_logger.add_appender(
  io: STDOUT,
  level: config.log_level,
  formatter: :son
)

Would result in a single appender, going to standard out.

However, when using the rails server (in development, for example), a default appender is still added, so we see duplicate logs (one :json format, one :color format).

[reidmorrison]

Make sure you are setting config.rails_semantic_logger.add_file_appender = false in a before initializer otherwise rails will create the default logger. Setting it after the default file appender has been added is too late.

[reidmorrison]

Changes have been made in master to replace several builtin Rails subscribers instead of patching them. It should help with the ongoing patching issues and loading order.
Give master a try locally and let us know if you run into any issues.

[eprothro]

@reidmorrison thanks for the comments. I've tried master and doesn't see a change with respect to this issue. I should be more clear though, I've conflated two things that I'm realizing aren't necessarily related.

Expectation

Let's say the user's goal is "I want to log to standard out and that's it".

The language in the docs on this indicate that the following would result in only a single appender, going to STDOUT.

config.rails_semantic_logger.add_file_appender = false
config.semantic_logger.add_appender(
  io: STDOUT,
  level: config.log_level,
  formatter: :json
)

Behavior

In reality, after the application is configured, there are two appenders.

In our example, for each application line logged, we would see two printed to STDOUT, one in :json format and one in :color format.

This is due to the Rails::Server monkey patch setting up log_to_stdout.

Overwriting log_to_stdout to perform no operation works around this issues

# workaround for https://github.com/rocketjob/rails_semantic_logger/issues/66
# which would result in duplicate logs on STDOUT if `rails s` is used
# if defined?(Rails::Server)
#   module Rails #:nodoc:
#     class Server #:nodoc:
#       private

#       def log_to_stdout
#         # SemanticLogger.add_appender(io: $stdout, formatter: :color)
#       end
#     end
#   end
# end

Running with another application server (e.g. puma instead of rails s) works as expected.

Comments

After thinking further, this issue is unrelated to Semantic Logger's handling of the add_file_appender=false. The issue is really that rails server is still calling log_to_stdout and there isn't an option to turn that off.

However, I believe the user confusion still remains. IMO, at least some additional clarity in the documentation is needed to address this issue.

In other words, it is probably unreasonable to expect Semantic Logger's definition of log_to_stdout to become "only log to standard out if no other appender is logging to standard out".

If we wanted to address with more than just documentation, one idea is to introduce an additional option to disable the rails server STDOUT appender...

config.rails_semantic_logger.add_file_appender = false
config.rails_semantic_logger.add_rails_server_stdout_appender = false
config.semantic_logger.add_appender(
  io: STDOUT,
  level: config.log_level,
  formatter: :json
)

[reidmorrison]

Logging to standard out is controlled by Rails. To turn it off, it needs to be run as a daemon in the development environment, or looking at the code it turns off automatically in non-development environments.

https://github.com/rails/rails/blob/master/railties/lib/rails/commands/server/server_command.rb#L145

We run puma instead of starting a rails server: bin/puma in test and prod environments which appears to turn off Rails standard out output.

If you run bin/puma even in development mode it turns off the Rails built-in stdout logging.

[eprothro]

We do the same, however some of our devs use rails s on occasion, so we wanted this work the same for them.

I think it would be worth adding a sentence or two to this effect in the docs here: http://rocketjob.github.io/semantic_logger/rails.html#disable-default-rails-file-logging

At any rate, I'm glad this issue discussion is here now for any others running into this. Thanks!

[reidmorrison]

Documentation updated with a note about this behavior in Rails itself

[artemave]

Use rails s --no-log-to-stdout to disable default stdout log in development.