Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Already on GitHub? Sign in to your account

activesupport changes logging format #363

Closed
auxbuss opened this Issue Mar 15, 2012 · 7 comments

Comments

Projects
None yet
4 participants

auxbuss commented Mar 15, 2012

@rkh asked me to post this here. It was originally posted as a sinatra issue here: sinatra/sinatra#483

logger.info "info message"

usually produces
>> Listening on 0.0.0.0:9292, CTRL+C to stop I, [2012-03-12T11:25:34.445953 #8526] INFO -- : info message

But adding:

require 'active_support/all'

changes the output to:

>> Listening on 0.0.0.0:9292, CTRL+C to stop info message

I'm not directly using activesupport, it is a gem dependency. Is there a way to reset the logger format?

I tried the following, but it had no effect:

before do
  logger.datetime_format = "%H:%M:%S"
end

sinatra (1.3.2)
activesupport (3.2.2)

Contributor

josevalim commented Mar 15, 2012

If is fixed on Rails 4 afaik. We are no longer changing the Logger class directly.

Owner

chneukirchen commented Mar 15, 2012

This is obviously a activesupport issue, no?

Member

tenderlove commented Mar 15, 2012

@chneukirchen yes, this is definitely an AS issue.

@auxbuss as @josevalim says, this will be fixed in Rails 4. To get around the issue today, you can do this:

require 'active_support/all'

logger = Logger.new $stdout

# Set back to default formatter
logger.formatter = Logger::Formatter.new

@tenderlove tenderlove closed this Mar 15, 2012

auxbuss commented Mar 15, 2012

Thanks. But while this does reset the log format to its default, thereafter, logger does not respond to datetime_format. So, it's not possible to change the log format.

Not sure why this was closed as the fix hadn't been confirmed. Troubling that I can't reopen either.

Member

tenderlove commented Mar 15, 2012

Sorry, it's closed because this isn't a bug in rack. If you look at the datetime_format method in the logger source, you'll see that it only operates on the "default formatter", and in fact it just passes the values on to the datetime_format on the formatter.

The default formatter is an instance of Logger::Formatter, but the trouble is that assigning a formatter does not impact the default formatter.

Armed with this knowledge, we can adjust the datetime formatter on our "custom" formatter:

require 'active_support/all'

logger = Logger.new $stdout

# Set back to default formatter
logger.formatter = Logger::Formatter.new

logger.formatter.datetime_format = "%Y"

logger.debug "omg!"

"But how can I tell if this is necessary?" is the question you might be asking yourself. Fortunately, we can programatically detect when ActiveSupport has screwed up the logger from stdlib. ActiveSupport will set the @formatter, so we can use that to differentiate between when AS has messed us up, and when it hasn't. Compare the output of the formatter method when AS is loaded, and when it isn't:

[aaron@mobile002 ~]$ ruby -rlogger -e'p Logger.new($stdout).formatter'
nil
[aaron@mobile002 ~]$ ruby -rlogger -ractive_support/all -e'p Logger.new($stdout).formatter'
#<Logger::SimpleFormatter:0x007ffb50b2d290 @datetime_format=nil>
[aaron@mobile002 ~]$

Using this differing behavior, we can conditionally set a formatter. When the code is upgraded to use Rails 4, the conditional may be removed:

require 'active_support/all'

# uncomment the line below and comment out AS to see it work the same
# require 'logger'

logger = Logger.new $stdout

if logger.formatter # AS has monkeypatched us.
  # This branch can be removed when Rails 4 is released

  # Set back to default formatter
  logger.formatter = Logger::Formatter.new
  logger.formatter.datetime_format = "%Y"
else
  logger.datetime_format = "%Y"
end

logger.debug "omg!"

Hope that helps!

auxbuss commented Mar 15, 2012

Much appreciate the reply, Aaron. Note that I only came here on request and I started this quest simply wondering why my log messages suddenly changed format in sinatra.

I can't even remember the package that dragged in Activesupport, which started the whole thing. It took a while to isolate Activesupport, because that wasn't possible within the original project. So, it's not like I haven't done a bunch of leg work before bringing the issue here.

I appreciate it's not a rack bug, but I raised the issue on sinatra, for obvious reasons, and was told to come here. I think that was good advice, as I suspect taking it to activesupport wouldn't have elicited a response, let alone a fix.

I'm left wondering why logging is so difficult -- at least, in sinatra. This has been clear for a while, and googling sinatra logging does nothing but add to the woes in this area. And, frankly, logging should not be this hard.

Once again, I really appreciate you spending the time to spell out what's going on.

Member

tenderlove commented Mar 16, 2012

@auxbuss no sweat! I guess the "real" place to file a ticket would have been the Rails tracker, since this is definitely a bug in ActiveSupport. @josevalim and I are on the Rails team, and we try to keep keep up with all the tickets. Monkey patches are a pet peeve of mine, so I'm sure I would have given the same support on the rails tracker. 😉

Anyway, yes. Logging should not be this difficult. It's very annoying that ActiveSupport monkeypatched the stdlib logger, but I hope my work-around will get you productive again.

@sanemat sanemat referenced this issue in cookpad/chanko Apr 17, 2013

Closed

[spike] Test against rails4 with appraisal #30

@kevin-alpine kevin-alpine pushed a commit to kevin-alpine/chorus-upgrade that referenced this issue May 20, 2015

@kevinmtrowbridge kevinmtrowbridge [rails 4 upgrade] Fixing broken spec:
1) QC adds timestamps to clockwork logs
     Failure/Error: Clockwork.config[:logger].instance_variable_get(:@formatter).instance_variable_get(:@datetime_format).should eq("%Y-%m-%d %H:%M:%S")

       expected: "%Y-%m-%d %H:%M:%S"
            got: nil

       (compared using ==)
     # ./spec/services/service_scheduler_spec.rb:153:in `(root)'

Basically, the internals of "active_support/core_ext/logger" change between Rails 3 and 4.

Here you can see an example of how a similar change was made in the Rails 4 tests:
rails/rails@572c3d5#diff-0352737d52430cb9ecf5938c20eb4ce6R18

Here's some more discussion:
rack/rack#363
39393fa

@kevin-alpine kevin-alpine pushed a commit to kevin-alpine/chorus-upgrade that referenced this issue May 20, 2015

@kevinmtrowbridge kevinmtrowbridge [rails 4 upgrade] Fixing broken spec:
1) QC adds timestamps to clockwork logs
     Failure/Error: Clockwork.config[:logger].instance_variable_get(:@formatter).instance_variable_get(:@datetime_format).should eq("%Y-%m-%d %H:%M:%S")

       expected: "%Y-%m-%d %H:%M:%S"
            got: nil

       (compared using ==)
     # ./spec/services/service_scheduler_spec.rb:153:in `(root)'

Basically, the internals of "active_support/core_ext/logger" change between Rails 3 and 4.

Here you can see an example of how a similar change was made in the Rails 4 tests:
rails/rails@572c3d5#diff-0352737d52430cb9ecf5938c20eb4ce6R18

Here's some more discussion:
rack/rack#363
60a1010

@kevin-alpine kevin-alpine pushed a commit to kevin-alpine/chorus-upgrade that referenced this issue May 22, 2015

@kevinmtrowbridge kevinmtrowbridge [rails 4 upgrade] Fixing broken spec:
1) QC adds timestamps to clockwork logs
     Failure/Error: Clockwork.config[:logger].instance_variable_get(:@formatter).instance_variable_get(:@datetime_format).should eq("%Y-%m-%d %H:%M:%S")

       expected: "%Y-%m-%d %H:%M:%S"
            got: nil

       (compared using ==)
     # ./spec/services/service_scheduler_spec.rb:153:in `(root)'

Basically, the internals of "active_support/core_ext/logger" change between Rails 3 and 4.

Here you can see an example of how a similar change was made in the Rails 4 tests:
rails/rails@572c3d5#diff-0352737d52430cb9ecf5938c20eb4ce6R18

Here's some more discussion:
rack/rack#363
b7f6c6f
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment