Ferret talk - Apr 2007 - Inifinite loop problem with DRb server

Hi all,

We''re attempting to use Ferret with the DRb server at the moment, and
it doesn''t work, at all...

= Executive Summary

The DRb server process keeps on calling the remote index to the DRb
server process...  Which means DRb is calling itself, and itself, and
itself, until Ruby kills the Thread with a SystemStackLevel error.

= The excruciating details...

# Mongrel is started using:
mongrel_rails start --port 6543 --environment development --daemonize
2>&1

# config/ferret_server.yml
development:
  host: 127.0.0.1
  port: 3000
  pid_file: log/ferret.3000.pid

# Ferret''s DRb server is started using:
script/runner -e development vendor/plugins/acts_as_ferret/script/ferret_start

# app/models/email.rb:
class Email < ActiveRecord::Base
  acts_as_ferret :store_class_name => true, :remote => true,
      :fields => (self.content_columns.map(&:name) rescue []) +
%w(main_identifier party_display_name)
end

# app/controllers/search_controller.rb
class SearchController < ApplicationController
  def quick
    @results = Email.id_multi_search(params[:q], %w(Contact Company))
  end
end

# Backtrace
stack level too deep

(druby://127.0.0.1:3000) /usr/local/lib/ruby/1.8/drb/drb.rb:1649:in
`current_server''
(druby://127.0.0.1:3000) /usr/local/lib/ruby/1.8/drb/drb.rb:1704:in
`to_obj''
(druby://127.0.0.1:3000) /usr/local/lib/ruby/1.8/drb/drb.rb:1079:in
`method_missing''
(druby://127.0.0.1:3000)
/home/francois/src/xlsuite.org/vendor/plugins/acts_as_ferret/lib/remote_index.rb:25:in
`id_multi_search''
(druby://127.0.0.1:3000)
/home/francois/src/xlsuite.org/vendor/plugins/acts_as_ferret/lib/ferret_server.rb:69:in
`send''
(druby://127.0.0.1:3000)
/home/francois/src/xlsuite.org/vendor/plugins/acts_as_ferret/lib/ferret_server.rb:69:in
`method_missing''
/home/francois/src/xlsuite.org/vendor/plugins/acts_as_ferret/lib/remote_index.rb:25:in
`id_multi_search''
/home/francois/src/xlsuite.org/vendor/plugins/acts_as_ferret/lib/class_methods.rb:117:in
`id_multi_search''
/home/francois/src/xlsuite.org/app/controllers/search_controller.rb:9:in
`quick''

$ rake log:clear && sleep 50 && du -h log/ferret*
(in /home/francois/src/xlsuite.org)
4.0K    log/ferret.3000.pid
0       log/ferret_index.log
229M    log/ferret_server.log
4.0K    log/ferret_server.out

There''s nothing really useful in ferret_server.log: only the same
backtrace that I showed above.

module ActsAsFerret
  module Remote
    class Server
      # vendor/plugins/acts_as_ferret/lib/ferret_server.rb:65
      def method_missing(name, *args)
        clazz = args.shift.constantize
        begin
          @logger.debug "call index method: #{name} with
#{args.inspect}"
          clazz.aaf_index.send name, *args
        rescue NoMethodError
          @logger.debug "no luck, trying to call class method instead"
          clazz.send name, *args
        end
      rescue
        @logger.error "ferret server error #{$!}\n#{$!.backtrace.join
''\n''}"
        raise
      end
    end
  end
end

When I change the logging statement inside the first begin/rescue clause of:
http://projects.jkraemer.net/acts_as_ferret/browser/trunk/plugin/acts_as_ferret/lib/ferret_server.rb#L68

I get this (see patch at end of message):
ActsAsFerret::Server#method_missing calling:
Email.id_multi_search(["*position*", ["Contact",
"Company", "Email"],
{}])
ActsAsFerret::Server#method_missing calling:
Email.id_multi_search(["*position*", ["Contact",
"Company", "Email"],
{}])
ActsAsFerret::Server#method_missing calling:
Email.id_multi_search(["*position*", ["Contact",
"Company", "Email"],
{}])
ActsAsFerret::Server#method_missing calling:
Email.id_multi_search(["*position*", ["Contact",
"Company", "Email"],
{}])
...

In total, there are 816 calls to #method_missing before Ruby gives up
and raises.

From my limited understanding of the code, it looks like the Ferret
DRb server is using a remote index instead of a local one.

This is all using the Rails 1.2 stable branch with r179 of the
acts_as_ferret plugin and the Ferret gem at 0.11.3.

So, what have we configured wrong ?

Thanks !
-- 
Fran?ois Beausoleil
http://blog.teksol.info/
http://piston.rubyforge.org/



$ svn diff vendor/plugins/acts_as_ferret/
Index: vendor/plugins/acts_as_ferret/lib/ferret_server.rb
==================================================================---
vendor/plugins/acts_as_ferret/lib/ferret_server.rb  (revision 179)
+++ vendor/plugins/acts_as_ferret/lib/ferret_server.rb  (working copy)
@@ -65,7 +65,8 @@
     def method_missing(name, *args)
       clazz = args.shift.constantize
       begin
-        @logger.debug "call index method: #{name} with
#{args.inspect}"
+        @logger.debug "ActsAsFerret::Server\#method_missing calling:
#{clazz.name}.#{name}(#{args.inspect})"
+        #raise "auto block"
         clazz.aaf_index.send name, *args
       rescue NoMethodError
         @logger.debug "no luck, trying to call class method instead"

On Tue, Apr 03, 2007 at 03:34:11PM -0400, Fran?ois Beausoleil
wrote:
> Hi all,
> 
> We''re attempting to use Ferret with the DRb server at the moment,
and
> it doesn''t work, at all...
> 
> = Executive Summary
> 
> The DRb server process keeps on calling the remote index to the DRb
> server process...  Which means DRb is calling itself, and itself, and
> itself, until Ruby kills the Thread with a SystemStackLevel error.
> 
[..]
> 
> From my limited understanding of the code, it looks like the Ferret
> DRb server is using a remote index instead of a local one.
I''d guess that''s the problem. The decision what indexer to use
is made
in act_methods.rb, line 62, depending on the state of
ActsAsFerret::Remote::Server.running

So if the acts_as_ferret method would be called before the DRb server is
up and running what you describe could happen. Maybe there''s some code
in your environment.rb that causes the loading of your model classes by
script/runner before the server gets a chance to start up?

As I think of it now, the way how this is done might not be the ideal
solution to the problem of deciding whether acts_as_ferret is called in
the DRb-server or not - an environment variable set when
starting the server and checking this in act_methods.rb instead of the
server''s running method might help:

IS_SERVER=true script/runner -e development
vendor/plugins/acts_as_ferret/script/ferret_start

and in act_methods line 62:

options.delete(:remote) if ENV[''IS_SERVER'']

Jens


-- 
Jens Kr?mer
webit! Gesellschaft f?r neue Medien mbH
Schnorrstra?e 76 | 01069 Dresden
Telefon +49 351 46766-0 | Telefax +49 351 46766-66
kraemer at webit.de | www.webit.de
 
Amtsgericht Dresden | HRB 15422
GF Sven Haubold, Hagen Malessa

Hello Jens,

2007/4/4, Jens Kraemer <kraemer at webit.de>:
> On Tue, Apr 03, 2007 at 03:34:11PM -0400, Fran?ois Beausoleil wrote:
> > The DRb server process keeps on calling the remote index to the DRb
> > server process...  Which means DRb is calling itself, and itself, and
> > itself, until Ruby kills the Thread with a SystemStackLevel error.
> >
> [..]
>
> I''d guess that''s the problem. The decision what indexer
to use is made
> in act_methods.rb, line 62, depending on the state of
> ActsAsFerret::Remote::Server.running
Yup, you hit the nail on the head.  I require app/models/*.rb at the
end of config/environment.rb.  I can''t test this right now, but
I''ll
try it when I get back to my office.

Your idea of using an ENV variable is probably a good idea.

I''ll see about creating a patch for that.

Thanks !
-- 
Fran?ois Beausoleil
http://blog.teksol.info/
http://piston.rubyforge.org/

Fran?ois Beausoleil wrote:
> 2007/4/4, Jens Kraemer <kraemer at webit.de>:
>> On Tue, Apr 03, 2007 at 03:34:11PM -0400, Fran?ois Beausoleil wrote:
>> > The DRb server process keeps on calling the remote index to the
DRb
>> > server process...  Which means DRb is calling itself, and itself,
and
>> > itself, until Ruby kills the Thread with a SystemStackLevel error.
>> >
>> [..]
>>
>> I''d guess that''s the problem. The decision what
indexer to use is made
>> in act_methods.rb, line 62, depending on the state of
>> ActsAsFerret::Remote::Server.running
> 
> Yup, you hit the nail on the head.  I require app/models/*.rb at the
> end of config/environment.rb.  I can''t test this right now, but
I''ll
> try it when I get back to my office.
I had the same problem, with acts_as_ferret''s ferret_server.log being 
around 101 MB for every DRb request that resulted with 
"SystemStackError: stack level too deep".

Removing the lines that required the models from my environment.rb 
definitely did the trick.

-- 
Posted via http://www.ruby-forum.com/.

Hi !

2007/4/4, Jens Kraemer <kraemer at webit.de>:
> As I think of it now, the way how this is done might not be the ideal
> solution to the problem of deciding whether acts_as_ferret is called in
> the DRb-server or not - an environment variable set when
> starting the server and checking this in act_methods.rb instead of the
> server''s running method might help:
I changed Ferret''s implementation with this patch:

$ svn diff vendor/plugins
Index: vendor/plugins/acts_as_ferret/lib/ferret_server.rb
==================================================================---
vendor/plugins/acts_as_ferret/lib/ferret_server.rb  (revision 4125)
+++ vendor/plugins/acts_as_ferret/lib/ferret_server.rb  (working copy)
@@ -63,9 +63,9 @@
     # TODO: rebuild indexes in separate directory so no lock errors in these
     # cases.
     def method_missing(name, *args)
+      @logger.debug "\#method_missing(#{name.inspect},
#{args.inspect})"
       clazz = args.shift.constantize
       begin
-        @logger.debug "call index method: #{name} with
#{args.inspect}"
         clazz.aaf_index.send name, *args
       rescue NoMethodError
         @logger.debug "no luck, trying to call class method instead"
Index: vendor/plugins/acts_as_ferret/lib/act_methods.rb
==================================================================---
vendor/plugins/acts_as_ferret/lib/act_methods.rb    (revision 4125)
+++ vendor/plugins/acts_as_ferret/lib/act_methods.rb    (working copy)
@@ -59,11 +59,15 @@

       # force local mode if running *inside* the Ferret server - somewhere the
       # real indexing has to be done after all :-)
-      options.delete(:remote) if ActsAsFerret::Remote::Server.running
+      logger.debug {"Asked for a remote server ?
#{options[:remote].inspect}, ENV[\"FERRET_USE_LOCAL_INDEX\"] is
#{ENV["FERRET_USE_LOCAL_INDEX"].inspect}, server is
#{ActsAsFerret::Remote::Server.running ? :running : :not_running}"}
+      options.delete(:remote) if ENV["FERRET_USE_LOCAL_INDEX"] ||
ActsAsFerret::Remote::Server.running

       if options[:remote] && options[:remote] !~ /^druby/
         # read server location from config/ferret_server.yml
         options[:remote]
ActsAsFerret::Remote::Config.load("#{RAILS_ROOT}/config/ferret_server.yml")[:uri]
+        logger.debug {"Will use a remote index server which should be
available at #{options[:remote]}"}
+      else
+        logger.debug {"Will use a local index"}
       end



That resolved my problem when I start the DRb server using:
$ FERRET_USE_LOCAL_INDEX=1 script/runner -e development
vendor/plugins/acts_as_ferret/script/ferret_start

BTW, my models are loaded because I have AR observers.

Thanks !
-- 
Fran?ois Beausoleil
http://blog.teksol.info/
http://piston.rubyforge.org/

On Thu, Apr 05, 2007 at 05:15:51PM -0400, Fran?ois Beausoleil
wrote:
> Hi !
> 
> 2007/4/4, Jens Kraemer <kraemer at webit.de>:
> > As I think of it now, the way how this is done might not be the ideal
> > solution to the problem of deciding whether acts_as_ferret is called
in
> > the DRb-server or not - an environment variable set when
> > starting the server and checking this in act_methods.rb instead of the
> > server''s running method might help:
> 
> I changed Ferret''s implementation with this patch:
[..]

Thanks, this is now part of trunk.

Jens

-- 
Jens Kr?mer
webit! Gesellschaft f?r neue Medien mbH
Schnorrstra?e 76 | 01069 Dresden
Telefon +49 351 46766-0 | Telefax +49 351 46766-66
kraemer at webit.de | www.webit.de
 
Amtsgericht Dresden | HRB 15422
GF Sven Haubold, Hagen Malessa