And so I was away on holiday for a month. First day back at work, I updated my workspace - git checkout, bundle update and all that.
Started development, I had to look at my Raild development log for some information and I was surprised to see cache operations messages cluttering the log. Challenge accepted! I put on my detective hat and let the investigation begins.
Below is an example of cache messages on the development log:
Cache generate: users/237-20111101044147 ({:expires_in=>3 days})
Cache write: users/237-20111101044147 ({:expires_in=>3 days})
Hundreds of them - very annoying. As always, I suspect Rails upgrade first. My colleague had upgraded Rails to the latest version 3.2.3. So first thing was to look at Rails upgrade notes. Read it - there doesn’t seem to be any changes with caching.
Diving into Rails source
Feeling adventurish, I took the next step, which was to look at Rails source code.
First thing is to ask bundle the location of the installed Rails gem. You can do show by issuing the following:
bundle show rails
Once inside the rails directory, I need to know what files that outputs the words “Cache generate”. I use the excellent Ack for this task - but grep would work as well.
ack 'Cache generate' .
I didn’t get any hit. I think I should be more general with search term and then tried:
ack 'Cache' .
Now we are getting somewhere, I noticed this snippet from ack:
logger.debug("Cache #{operation}: #{key}#{options.blank? ? "" : " (#{options.inspect})"}")
I suspected this line is the culprit. That line is from lib/active_support/cache.rb - so I opened that file up and try to understand what the code does.
At line 526 - I saw this the code in its context:
def log(operation, key, options = nil)
return unless logger && logger.debug? && !silence?
logger.debug("Cache #{operation}: #{key}#{options.blank? ? "" : " (#{options.inspect})"}")
end
It looks like to turn off the logger statements, I needed to either:
- Set the logger.debug to false
- Or set the silence! to true
But before doing that, I just want to make sure that I was looking at the right code. So I did the hackiest way to find out by changing the line 526 to output my own statement, this is an example:
logger.debug("hello world")
I then did a test. I fired up the trusty pry (which is indispensible btw) and boot up Rails console. I did the following:
pry> Rails.cache.write("hello","world")
Now if I was hacking the correct Rails code - I would expect the string “hello world” to be printed on my Rails development log. But to my surprise it didn’t - my modification to Rails code was not being executed.
This tells me - that perhaps this piece of Rails code was overriden somewhere. My hunch told me that I should check Dalli gem
- as this is the gem that we use as Memcached client.
I also quickly had a look at the git history of Gemfile.lock and sure enough this gem has also been recently updated.
Performing the same ack search on the Dalli source code finally got me to the the root of the issue. Found that Dalli overrides ActiveSupport::Cache.log. Let’s look at the code that can be found at: lib/active_support/cache/dalli_store.rb line 204:
def log(operation, key, options=nil)
return unless logger && logger.debug?
logger.debug("Cache #{operation}: #{key}#{options.blank? ? "" : " (#{options.inspect})"}")
end
Now once more, I performed the hack to output debug statements to confirm that I was looking at the right place. My suspicion was confirmed - this is the code that outputs the logging statements.
Now, the code looks different to the ActiveSupport code that it’s overriding - noticable different is the missing silence! checking here. My suspicion is, the gem has not been updated to reflect changes in Rails ActiveSupport.
And as a good Open Source citizen I raised an issue on the project: Issue 207. I would attempt at creating Pull Request - but thing is I am not confident that I got it right, so I thought of asking first.
The Dalli gem creator, Mike Perham (@mperham was vert helpful. Shortly after I raised th issue that he implemented the missing silence method.
Solution
With the silence! method incorporated, simply create a Rails initializer with the following:
Rails.cache.silence!
BUT, that’s not the only solution - remember that logger.debug? condition? Turns out that in development env - the log level default is debug.
Ths is the quote from Ruby on Rails guide:
The default Rails log level is info in production mode and debug in development and test mode
So you could set the log level to other than than debug (info for instance) - but I don’t think this is correct way - I mean it makes sense that the logger should be in debug level for development.
Summary
Master the power of bundle open/show and reading/hacking code so that you can level up as a Rails developer.
Contribute contribute in whatever way you can to Open Source - documentation, reporting issues, pull requests.