Rails 3 Not Logging in Development

Question

I've tried calling both logger.debug and Rails.logger.debug but nothing is getting outputted to the development.log file. Any ideas as to what's going?

Update

I should also note that I'm calling this from a controller and that other information such as the SQL queries are getting outputted to the log file.

Source Code

https://github.com/kyledecot/skateparks-web

Gemfile

source 'http://rubygems.org/'

gem 'rails', '3.0.7'
gem 'rake', '~> 0.8.7'
gem 'devise'
gem 'omniauth'
gem 'flash_cookie_session'
gem 'carrierwave'
gem 'mini_magick'
gem 'barometer'
gem 'gdata_19', :require => 'gdata'
gem 'google_places'
gem 'fleakr'
gem 'resque'
gem 'nokogiri'
gem 'decent_exposure'
gem 'cancan'
gem 'friendly_id'
gem 'breadcrumbs_on_rails'
gem 'defensio'
gem 'twitter'
gem 'thinking-sphinx', :require => 'thinking_sphinx'
gem 'ts-resque-delta', '1.0.0', :require => 'thinking_sphinx/deltas/resque_delta'
gem 'mime-types', :require => 'mime/types'
gem 'vpim'
gem 'will_paginate', '~> 3.0.pre2'
gem 'acts_as_geocodable'
gem 'acts_as_audited', '2.0.0.rc7'
gem 'passenger'
gem 'paper_trail'
gem 'thin'
gem 'compass', '>= 0.11.1'
gem 'guard-compass'
gem 'redcarpet'
gem 'mysql2', '0.2.7'
gem 'placemaker'

group :development, :test do

  gem 'sqlite3'
  gem 'capybara'  
  gem 'launchy'
  gem "rspec-rails"
  gem 'rb-fsevent', :require => false if RUBY_PLATFORM =~ /darwin/i
  gem 'guard-rspec'
  gem 'guard-bundler'
  gem 'guard-delayed'
  gem 'factory_girl'
  gem 'rspec'

end

group :production do 
end

enviornment.rb

require File.expand_path('../application', __FILE__)
Skateparks::Application.initialize!
ActiveRecord::Base.logger.level = Logger::INFO

ImagesController

def server
  logger.warn "WARN!" # nothing
  logger.info "INFO!" # nothing
  logger.debug "DEBUG!" # nothing
  puts Rails.logger.inspect # shows
  puts "PUTS!" # shows
end

Log Output w/ rails s

#<ActiveSupport::BufferedLogger:0x000001058867a0 @level=0, @buffer={}, @auto_flushing=1, @guard=#<Mutex:0x000001058866b0>, @log=#<File:/Users/Kyle/Desktop/skateparks-web/log/development.log>>
PUTS!


Started GET "/images/fd3b38315c30532b3a55bb84d35e5925/34_m.png" for 127.0.0.1 at 2011-06-29 03:41:50 -0400
  User Load (0.3ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1

Answer 1

UPDATE:

Viget Labs has removed the loggable gem from their repo ( https://github.com/vigetlabs/loggable )

---

Some gem in your app is using the vigetlabs/loggable gem. Looking at Gemfile.lock, it appears that the "fleakr" gem is using it.

I noted that while logger.info "hello" does not work, Rails.logger.info "hello" works just fine.

It appears the loggable gem is somehow redefining the logger methods to do nothing using the LoggerStub:

class LoggerStub
  
  [:debug, :error, :fatal, :info, :warn].each do |method|
    class_eval <<-CODE
      def #{method}(message); nil; end
    CODE
  end
  
end

What is happening is that the loggable gem is defining a class variable and instance variable called logger, and the .info etc methods are being called on one of them. And those methods simply return nil.

I know this is a partial answer (in that it is not a complete solution), but that should be good information to get you started on finding the proper solution.

Take a look also at these files:

1. log_methods.rb
2. logger_stub.rb

UPDATE

Adding..

class ActionController::Base
    self.class.logger = Rails.logger
end

..should forcibly override loggable's assignment of the logger and things should work normally. I suppose the same would work for class ActiveRecord::Base.

But of course, this is a brute force solution that does not fix the underlying problem. For a real "fix" you would need to delve further into fleakr or loggable and maybe ask about this problem at the issues page for those gems.

UPDATE

See if you can make the fleakr gem use the loggable fork from mediashelf : that fork should use the default Rails logger if it is available.