Queries are logged twice when using a STDOUT logger in the Rails 4 console #11415

Closed
davidbalbert opened this Issue Jul 12, 2013 · 36 comments
@davidbalbert

I've found what I believe to be a regression in Active Record's logging behavior inside the Rails console in Rails 4. If I set config.logger to log to STDOUT, all the database queries logged to the console get logged twice.

Here are the steps to reproduce:

$ rails --version
Rails 4.0.0
$ rails new test_logger
$ cd test_logger

Edit config/environments/development.rb and add these two lines in the configure block:

config.logger = ActiveSupport::Logger.new(STDOUT)
config.logger.level = ActiveSupport::Logger.const_get(ENV['LOG_LEVEL'] ? ENV['LOG_LEVEL'].upcase : 'DEBUG')

$ rails g model User name:string
$ rake db:migrate

$ rails c
Loading development environment (Rails 4.0.0)
2.0.0-p247 :001 > User.first
  User Load (0.2ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1
  User Load (0.2ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1
 => nil 
2.0.0-p247 :002 > 

I expect the "User Load" line to appear only once, but it appears twice. I can reproduce the bug both in Rails 4.0.0 and the latest master at the time of this writing. Following the same steps using Rails 3.2.13 (substituting Logger for ActiveSupport::Logger), the console works as expected.

I have also tried using Logger with the Rails 4 app. When I do this, the query is still logged twice, once using Ruby's default Formatter (as I would expect) and once using Rails's custom Formatter (unexpected):

rails c
Loading development environment (Rails 4.0.0)
2.0.0-p247 :001 > User.first
  User Load (0.3ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1
D, [2013-07-12T16:29:59.363272 #22484] DEBUG -- :   User Load (0.3ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1
 => nil 
2.0.0-p247 :002 > 

Please let me know if there's anything else I can do to help with this bug.

@gaurish

Confirmed.

I can reproduce this behaviour on master as well.

@senny
Ruby on Rails member

maybe related to #11060

@svoboda-jan

I can confirm this with ActiveRecord, but also with all log entries in rails server when config.logger = Logger.new(STDOUT) is set.

It is caused by extending the logger class:

In the case of the rails console: activerecord/lib/active_record/railtie.rb#L68

Rails.logger.extend ActiveSupport::Logger.broadcast console

In the case of rails server: railties/lib/rails/commands/server.rb#L81

Rails.logger.extend(ActiveSupport::Logger.broadcast(console))

with the following activesupport/lib/active_support/logger.rb#L10:

    # Broadcasts logs to multiple loggers.
    def self.broadcast(logger) # :nodoc:
      Module.new do
        define_method(:add) do |*args, &block|
          logger.add(*args, &block)
          super(*args, &block)
        end

        define_method(:<<) do |x|
          logger << x
          super(x)
        end
        # . . .
      end
    end

Normally, when logger is created automatically, without config.logger, only logger with output to file is created and the output to console is done by Logger#broadcast. When creating a new logger with config.logger = Logger.new(STDOUT), the broadcast is still in place, since the class was extended. This causes duplicate entries.

One workaround to disable logging to file and only enable console logging is the following:

config.paths["log"] = '/dev/null'
@n0nick

Seems related to/duplicate of #10977?

@evilsocket

👍 confirmed.

@guilleiguaran
Ruby on Rails member

Guys, I'm closing this in favor of the PR that fixes it: #11060

@guilleiguaran guilleiguaran reopened this Sep 23, 2013
@gmile

I'm still seeing the issue as of rails 4.0.2

@rurabe

Likewise

[2] pry(main)> Event.count
   (0.4ms)  SELECT COUNT(*) FROM "events"
   (0.4ms)  SELECT COUNT(*) FROM "events"
=> 0
@maxcal maxcal referenced this issue in remote-wind/remote-wind Feb 10, 2014
Closed

Very slow reponse times #52

@arthurnn
Ruby on Rails member

I cannot simulate this.. I guess it is fixed on latest version.. Can anyone post a example app of the problem?

thanks

@senny
Ruby on Rails member

@gmile @rurabe the merged patch #11060 was not backported to 4-0-stable. This behavior should be gone on master and 4-1-stable.

@senny senny closed this Apr 10, 2014
@andrielfn

I followed the steps described in the issue and I could reproduce it with master. I took a quick look and seems that it's being logged twice because we are instantiating a Logger here and now in development.rb. I don't know why it's happening in fact, I'll take a deeper look on it.

$ rails c
Loading development environment (Rails 4.2.0.alpha)
>> User.first
  User Load (0.1ms)  SELECT  "users".* FROM "users"   ORDER BY "users"."id" ASC LIMIT 1
  User Load (0.1ms)  SELECT  "users".* FROM "users"   ORDER BY "users"."id" ASC LIMIT 1
=> nil
@davidbalbert

Sorry to be AWOL. I just verified that I can still reproduce the bug on Rails 4.1. @senny, can we reopen this issue given that it's not yet fixed?

There's been a fair amount of confusion about #11060. That fixed a similar issue with rails server, but it did not fix this issue, which is a bug in rails console.

@arthurnn arthurnn reopened this Apr 10, 2014
@andrielfn

@davidbalbert Once Rails already logs for us in development environment, why are you trying to set it again in development.rb?

@davidbalbert

We use Unicorn in both production and development (we try to keep our dev/production environments as close together as possible). Because we're using unicorn and not rails s in development mode, our logs don't get tailed automatically for us. It's easy to fix this, by setting config.logger to log to stdout in development.rb, but then we get double the log output in the console.

A hacky solution would be something like this pseudocode:

# development.rb

unless in_console?
  config.logger = ...
end

but I'd obviously rather not have to do that.

@andrielfn

If I'm not wrong, the production environment that you specified seems to be a stage environment. In general, isn't good run an app in development environment if not in your own machine, because this environment has some particularities only for development mode (i.g. the logs itself, table names, etc), and it makes difficult keep both environments similar, as you said.

@davidbalbert

I think I wasn't as clear as I could have been. Sorry!

Our development environment is relatively unremarkable: we run it only on our own laptops and have not made many modifications to the default Rails development environment. The only difference is that we use Unicorn instead of rails server because we also use Unicorn in production and want to use the same app server in all of our environments. Using Unicorn in development requires us to log to stdout if we want to see our log output because Unicorn does not have the same log tailing behavior as rails server. We don't have a staging environment.

The issue is that setting Rails.logger to log to stdout in development leaves us with each database query logged twice in the console.

@rafaelfranca
Ruby on Rails member

@andrielfn maybe we should check if the logger is already present in the console block you pointed and only instantiate a new one on STDERR if it is not?

@andrielfn

I've done exactly this before and it worked, but I don't know if it can cause some wrong behaviour. What do you think?

@rafaelfranca
Ruby on Rails member

I don't think it would cause any wrong behavior but is good to test in an example application. Other options is check if the logger is pointing to STDERR and if that is the case we don't set the console log.

@andrielfn

Nice! I'll check that and proceed with a PR.

@rails-bot rails-bot added the stale label Aug 19, 2014
@rails-bot

This issue has been automatically marked as stale because it has not been commented on for at least
three months.

The resources of the Rails team are limited, and so we are asking for your help.

If you can still reproduce this error on the 4-1-stable, 4-0-stable branches or on master,
please reply with all of the information you have about it in order to keep the issue open.

Thank you for all your contributions.

@davidbalbert

I can still reproduce this with the latest release of Rails. It seems like there's a proposed solution in #14769 (have a configuration option to turn log broadcasting off), but there hasn't been any movement since April.

@rafaelfranca rafaelfranca removed the stale label Aug 20, 2014
@niedfelj

Let's fix this!

I ended up just putting this in config/application.rb after require 'rails/all' as I think broadcast is only used by console/server and since I use stdout logging everywhere with foreman I don't need it:

ActiveSupport::Logger.class_eval do 
  #monkey patching here so there aren't duplicate lines in console/server
  def self.broadcast(logger) 
    Module.new do
    end
  end
end
@ankane

@niedfelj thanks, works like a charm until things are sorted out!

@korbin
config.logger.define_singleton_method(:extend) {|*args| }

was my monkey patch to stop this issue, for anyone still seeing this.

@bronzle

/cc @rafaelfranca

I was just taking a look at this, do you think this: bronzle@447c39d would be a sufficient solution?

It just gives a logger_broadcast_console = (true/false) that is used by the server command to output to to STDOUT and AR::Railtie's console do block to output to $stderr

Thoughts?

@seanahrens

For anyone who stumbles upon this issue from google, make sure that what's actually happening to you is not that your app is actually making duplicate REQUESTS as mine was. See http://stackoverflow.com/questions/3266020/rails-app-logging-duplicate-requests/28299100#28299100

@hakunin

Still happening on rails 4.1.10

@benjaminb10

And still in 4.2.1

@zimbatm zimbatm referenced this issue in heroku/rails_stdout_logging Apr 9, 2015
Closed

Everything is logged twice in development #13

@dwbutler

I ended up adding this to application.rb:

console do
  ActiveRecord::Base.logger = Rails.logger = Logger.new(STDOUT)
end
@micahlmartin

@dwbutler That fixed it for me. I was still experiencing the issue in 4.2.3.

@philbattos

I was seeing duplicate logs in development but i discovered that it was caused by these two gems: rails_12factor and rails_stdout_logging. I added them based on Heroku's recommendation. When i removed them, everything worked great. (I'm going to keep using the gems but i thought this info might help someone.)

@raldred

Still present in fresh 4.2.4 app created today when running various rake tasks including migrations

@hosh

Same here as @philbattos I'm using rails_stdout_logging and seeing this console for dev mode.

@nwjsmith nwjsmith added a commit that referenced this issue Dec 14, 2015
@nwjsmith nwjsmith Add Logger option to disable message broadcasts
When setting the Rails logger to log to STDOUT, it would broadcast the
log twice in development. This adds a setting that will prevent messages
from being broadcast to multiple logs, while still allowing calls to
`#close`, `#level=`, `#progname=`, and `#formatter=` to be broadcasted.

Fixes #14769, #11415
c93f994
@nwjsmith nwjsmith added a commit that referenced this issue Dec 15, 2015
@nwjsmith nwjsmith Add Logger option to disable message broadcasts
When setting the Rails logger to log to STDOUT, it would broadcast the
log twice in development. This adds a setting that will prevent messages
from being broadcast to multiple logs, while still allowing calls to
`#close`, `#level=`, `#progname=`, and `#formatter=` to be broadcasted.

Fixes #14769, #11415
7ae6a3d
@nwjsmith nwjsmith added a commit that referenced this issue Dec 15, 2015
@nwjsmith nwjsmith Add Logger option to disable message broadcasts
When setting the Rails logger to log to STDOUT, it would broadcast the
log twice in development. This adds a setting that will prevent messages
from being broadcast to multiple logs, while still allowing calls to
`#close`, `#level=`, `#progname=`, and `#formatter=` to be broadcasted.

Fixes #14769, #11415
2e3688f
@nwjsmith

In my PR I've added an option to the logger to disable broadcasting messages to other loggers, so you'll be able to do the following in config/application.rb:

config.logger = ActiveSupport::Logger.new(STDOUT)
config.logger.level = ActiveSupport::Logger.const_get(ENV['LOG_LEVEL'] ? ENV['LOG_LEVEL'].upcase : 'DEBUG')
config.logger.broadcast_messages = false

and the log will no longer print to stdout twice.

@nwjsmith nwjsmith added a commit that referenced this issue Dec 16, 2015
@nwjsmith nwjsmith Add Logger option to disable message broadcasts
When setting the Rails logger to log to STDOUT, it would broadcast the
log twice in development. This adds a setting that will prevent messages
from being broadcast to multiple logs, while still allowing calls to
`#close`, `#level=`, `#progname=`, and `#formatter=` to be broadcasted.

Fixes #14769, #11415
e12ffb7
@nwjsmith

This has been fixed with #22592

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment