Redirect logger output for a specific controller in Rails 4

Question

I've built a solution based on the answer in my previous question Redirect logger output for a specific controller in Rails 3 for Rails 3. It works great however now I am trying to apply the same middleware based solution to a Rails 4 project but there are some differences keeping the same solution from working.

The Rails 3 solution:

module MyApp
  class LoggerMiddleware

    REPORTS_API_CONTROLLER_PATH = %r|\A/api/v.*/reports.*|
    REPORTS_API_CONTROLLER_LOGFILE = "reports_controller.log"

    def initialize(app)
      @app = app
      @logger = Rails::logger
           .instance_variable_get(:@logger)
           .instance_variable_get(:@log)
      @reports_api_controller_logger = Logger.new(
           Rails.root.join('log', REPORTS_API_CONTROLLER_LOGFILE), 
           10, 1000000)
    end

    def call(env)
      Rails::logger
           .instance_variable_get(:@logger)
           .instance_variable_set(:@log,
               case env['PATH_INFO']
               when REPORTS_API_CONTROLLER_PATH then
                 @reports_api_controller_logger
               else
                 @logger
               end
           )
      @app.call(env)
    end
  end
end

Rails.application.middleware.insert_before Rails::Rack::Logger, MyApp::LoggerMiddleware

in the above:

Rails 3 getter for Rails.logger = Rails::logger.instance_variable_get(:@logger).instance_variable_get(:@log)

Rails 3 setter for Rails.logger (setting to @my_logger) = Rails::logger.instance_variable_get(:@logger).instance_variable_set(:@log,@my_logger)

One thing I've noticed right away is that in Rails 4 the above Rails::logger.instance_variable_get(:@logger).instance_variable_get(:@log) returns nil.

Checking in Rails 4 console, I do see that Rails.instance_variable_get(:@logger) returns #<ActiveSupport::Logger:0x007f84ff503a08 ....>

I've tried replacing the getter with Rails.instance_variable_get(:@logger) and the setter with Rails.instance_variable_set(:@logger,my_logger) and it almost seems to work. The first part of the activity, the "Started..." goes to the new log file but everything after that goes to the default log file (the Rails.logger before the middleware changed it).

Either Rails.instance_variable_get(:@logger) is not the lowest level equivalent in Rails 4 to the Rails 3 Rails::logger.instance_variable_get(:@logger).instance_variable_get(:@log) for getting/setting the Rails.logger or there is something else later on in the process after my middleware that is overwriting this after I set it.

Any clues?

Update:

To clarify, the solution posted above works as expected in Rails 3. Any limitations it may or may not have in special environments (such as if the solution may not work in threading server environments if that is the case) are ok at this point and not experienced as obstacles at this time therefore these same limitations are also ok in a Rails 4 solution for this question.

Afaik the same logger instance is shared between threads, so if you use a threading server, or want to have an opportunity to do so in the future make sure to not switch output of parallel requests during the processing of the "special controller" (Puma + C Ruby threads are preferred Heroku deployment strategy now so the argument is not merely academical) — bbozo, Feb 04 '16 at 08:15
Hi @bbozo, thanks for the comment. We are not doing anything intentionally with a threading server at this time. Is it possible this is setup by default somewhere and I am not aware of it? If we decided to implement a "threading server" as you say, what modifications to this approach so we can have the same result would you suggest? — Streamline, Feb 08 '16 at 21:07
Hi @Streamline, Rails 4 applications are threaded per default. This change was introduced with Rails 4. In Rails 3 you had to explicitly enable multi thread support with `config.threadsafe!`. I assume that your Rails 4 application runs concurrent threads which are overriding the Rails.logger setting in a non-deterministic way. That would explain that it stops to work after a while. — Tawan, Feb 20 '16 at 20:33

score 6 · Answer 1 · answered Feb 16 '16 at 07:59

6

After hacking around the Rails code for a day, I think I have found a hack-ish solution to your problem.

You need to edit the call method and initialize method as follow:

def initialize(app)
  @app = app
  @logger = Rails.instance_variable_get(:@logger)
  @reports_api_controller_logger = Logger.new(
      Rails.root.join('log', REPORTS_API_CONTROLLER_LOGFILE),
      10, 1000000)
end

def call(env)
  if env['PATH_INFO'] =~ /api\/v.*\/reports.*/
    Rails.instance_variable_set(:@logger, @reports_api_controller_logger)
    ActionController::Base.logger = @reports_api_controller_logger
    ActiveRecord::Base.logger = @reports_api_controller_logger
    ActionView::Base.logger = @reports_api_controller_logger
  else
    Rails.instance_variable_set(:@logger, @logger)
    ActionController::Base.logger = @logger
    ActiveRecord::Base.logger = @logger
    ActionView::Base.logger = @logger
  end
  @app.call(env)
end

This is really a hack-ish solution and modify the regex according to your needs.

Tell me if this doesn't work for you.

answered Feb 16 '16 at 07:59

Jagjot

5,816
2
24
41

Works perfectly!! :D – Sankalp Singha Feb 16 '16 at 08:02
Hi @jagiot-singh, looks promising as I did a brief test with a limited setup of my Rails 4 app just a few minutes ago and it appears to be working. I wonder can anyone offer an explanation as to why in Rails 4 we seem to need to take a step backwards from Rails 3 and need to set each Base logger separately vs all using the same as in Rails 3? Or is there still a place where it does all inherit from the same source and we just haven't found it yet? I will investigate more later this week when I get a chance with the full setup of my Rails 4 app to see if it is all working as expected. – Streamline Feb 18 '16 at 00:58
@Streamline Rails 3 inherits the Log4r or default Ruby logger by default but its not the same with Rails 4. Rails 4 has different loggers for each part in `M(ActiveRecord)V(ActionView)C(ActionController)`. I have tried overriding ActiveSupport::LogSubscriber's logger which seems to be inherited by all of the above classes. But that method was not successful. Hence I modified each logger manually to achieve the result. – Jagjot Feb 18 '16 at 08:38
To keep tags, use `@reports_api_controller_logger = ActiveSupport::TaggedLogging.new(Logger.newRails.root.join('log', REPORTS_API_CONTROLLER_LOGFILE),10, 1000000)))` – user3033467 Dec 21 '17 at 10:23

score 0 · Answer 2 · edited May 23 '17 at 10:28

I'm not sure if you need to approach the solution in the same way as you had done in Rails 3. It seems there may be other ways to accomplish your end goal. Have you considered any of these approaches or gems?

https://github.com/TwP/logging

How to log something in Rails in an independent log file?

Sometimes trying something completely different than what you've already done can be helpful IMHO.

This is a bit of guess, but this may be why your getter setters are not working as expected: https://github.com/rails/rails/commit/6329d9fa8b2f86a178151be264cccdb805bfaaac

Regarding Jagjot's solution and needing to set base log for each of the MVC Action Classes, Rails 4 sets these separately by default which would in tern seem to provide more flexibility out of the box. http://guides.rubyonrails.org/configuring.html#initializers

score -1 · Answer 3 · answered Feb 13 '16 at 07:53

-1

The approach of using a different logging class for 1 controller has the downside that it won't work on a threading server which is in fashion these days not just with JRuby, but MRI too thanks to Heroku

Only idea I have so far after giving it a week of thought is to pipe the logs to syslog and use syslog's facilities to split them into separate files.

It would still require patching the Logger to include strings that would allow for the splitting (such as adding a formatted lined of from the #caller trace to the log files).

Plan B would be to introduce my own logger and simply log what I need in that controller. You could easily dump params and response for example if that's enough

answered Feb 13 '16 at 07:53

bbozo

7,075
3
30
56

Hi @bbozo, the issue you are describing of dealing with the threading server is not yet one I am faced with with as far as I know. At this point and for this particular SO question, I want to be able to do the same thing in Rails 4 that we are already doing in Rails 3 on our server today regardless of new issues a threading server may bring unless you are saying that this threading server is an integral part of Rails 4 independent of our server's setup and its not one we would see with Rails 3 anyway..? We don't use Heroku/Puma. We use Nginx/Passenger on an Ubuntu server in a Docker container. – Streamline Feb 13 '16 at 13:28
Your Plan B mentioned above, how would you do the "introduce my own logger" part since that seems to be a possible (albeit much more drastic) solution for my challenge regardless of the difference of a threading server being an issue or not. Would you replace the Rails::Rack::Logger middleware all together with your own middleware by deleting Rails::Rack::Logger and the inserting your own version in the stack? Is it possible to just monkey patch Rails::Rack::Logger without replacing the entire middleware with something different all together so updates can be used together with your changes? – Streamline Feb 13 '16 at 13:53
No, I would just open a file in the init script and output to it in the controller :) – bbozo Feb 13 '16 at 15:36
I digged a bit in the Rails code and found nothing, I waited a week for some other answer, but nothing came, so I'm guessing there's not many options out there – bbozo Feb 13 '16 at 15:38

Redirect logger output for a specific controller in Rails 4

3 Answers3

Linked