Logging inside threads in a Rails application

Question

I've got a Rails application in which a small number of actions require significant computation time. Rather than going through the complexity of managing these actions as background tasks, I've found that I can split the processing into multiple threads and by using JRuby with a multicore sever, I can ensure that all threads complete in a reasonable time. (The customer has already expressed a strong interest in keeping this approach vs. running tasks in the background.)

The problem is that writing to the Rails logger doesn't work within these threads. Nothing shows up in the log file. I found a few references to this problem but no solutions. I wouldn't mind inserting puts in my code to help with debugging but stdout seems to be eaten up by the glassfish gem app server.

Has anyone successfully done logging inside a Rails ruby thread without creating a new log each time?

Vinegary

Update: I found that puts in threads do show up in the glassfish log file. I'm not sure why I didn't see this before; I might have originally tested it in a thread spawned by another (non-main) thread. Anyway, for debugging purposes, I'm seeing writes to STDOUT in the log file so I'm happy. – Vinegary

Answer 1

I was scratching my head with the same problem. For me the answer was as follows:

Thread.new do
  begin
    ...
  ensure
    Rails.logger.flush
  end
end

Idaidae

Answer 2

I understand your concerns about the background tasks, but remember that spinning off threads in Rails can be a scary thing. The framework makes next to no provisions for multithreading, which means you have to treat all Rails objects as not being thread-safe. Even the database connection gets tricky.

As for the logger: The standard Ruby logger class should be thread safe. But even if Rails uses that, you have no control over what the Rails app is doing to it. For example the benchmarking mechanism will "silence" the logger by switching levels.

I would avoid using the rails logger. If you want to use the threads, create a new logger inside the thread that logs the messages for that operation. If you don't want to create a new log for each thread, you can also try to create one thread-safe logging object in your runtime that each of the threads can access.

In your place I'd probably have another look at the background job solutions. While DRb looks like a nightmare, "bj" seems nice and easy; although it required some work to get it running with JRuby. There's also the alternative to use a Java scheduler from JRuby, see http://www.jkraemer.net/2008/1/12/job-scheduling-with-jruby-and-rails

Debunk

Thanks for the info and suggestions, but at this point I'll stick with the threading approach since it's working fine except for logging. I'm not using any questionable gems/plugins in any of the threads and I'm careful about using mutexes to prevent race conditions. My interest in using the Rails logger was just ease of debugging and I've managed to get around that by using threads only if JRUBY_VERSION is defined and otherwise running the same code sequentially. Thanks anyway! – Vinegary