NameError: uninitialized constant ThinkingSphinx::ActiveRecord

[hennevogel]

After updating to 5.2.1 booting crashes in lib/thinking_sphinx/real_time/index/template.rb:33:in add_field'

Log: https://gist.github.com/hennevogel/f789fbcad4d9ce86351e54075ae5a318

This was introduced in ea35340 I think.

My app is a super simple (FOSS) app 👉🏿 https://github.com/SUSE/hackweek/

Just real time indices indexing text...

[pat]

Thanks for reporting this, and for having an app I can test it with 🙂

Although, I couldn't get quite the same issue, but got something similar (provided I was starting a console in production) - that is, the error is the same but the stack trace is different:

$ RAILS_ENV=production bundle exec rails c
Traceback (most recent call last):
       # ...
	45: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.6/lib/rails/initializable.rb:61:in `block in run_initializers'
	44: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.6/lib/rails/initializable.rb:32:in `run'
	43: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.6/lib/rails/initializable.rb:32:in `instance_exec'
	42: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.6/lib/rails/application/finisher.rb:68:in `block in <module:Finisher>'
	41: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/lazy_load_hooks.rb:51:in `run_load_hooks'
	40: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/lazy_load_hooks.rb:51:in `each'
	39: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/lazy_load_hooks.rb:52:in `block in run_load_hooks'
	38: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/lazy_load_hooks.rb:67:in `execute_hook'
	37: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/lazy_load_hooks.rb:62:in `with_execution_control'
	36: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/lazy_load_hooks.rb:69:in `block in execute_hook'
	35: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise/rails.rb:17:in `block in <class:Engine>'
	34: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.6/lib/rails/application.rb:168:in `reload_routes!'
	33: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.6/lib/rails/application/routes_reloader.rb:20:in `reload!'
	32: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.6/lib/rails/application/routes_reloader.rb:41:in `load_paths'
	31: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.6/lib/rails/application/routes_reloader.rb:41:in `each'
	30: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.6/lib/rails/application/routes_reloader.rb:41:in `block in load_paths'
	29: from /Users/pat/Code/tmp/hackweek/config/routes.rb:1:in `<top (required)>'
	28: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.6/lib/action_dispatch/routing/route_set.rb:414:in `draw'
	27: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.6/lib/action_dispatch/routing/route_set.rb:432:in `eval_block'
	26: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.6/lib/action_dispatch/routing/route_set.rb:432:in `instance_exec'
	25: from /Users/pat/Code/tmp/hackweek/config/routes.rb:4:in `block in <top (required)>'
	24: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise/rails/routes.rb:242:in `devise_for'
	23: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise/rails/routes.rb:242:in `each'
	22: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise/rails/routes.rb:243:in `block in devise_for'
	21: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise.rb:346:in `add_mapping'
	20: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise.rb:346:in `new'
	19: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise/mapping.rb:72:in `initialize'
	18: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise/mapping.rb:162:in `default_used_route'
	17: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise/mapping.rb:95:in `routes'
	16: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise/mapping.rb:78:in `modules'
	15: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise/mapping.rb:83:in `to'
	14: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/devise-4.8.0/lib/devise.rb:316:in `get'
	13: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/inflector/methods.rb:281:in `constantize'
	12: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/inflector/methods.rb:281:in `inject'
	11: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/inflector/methods.rb:281:in `each'
	10: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/inflector/methods.rb:283:in `block in constantize'
	 9: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/inflector/methods.rb:283:in `const_get'
	 8: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/dependencies/interlock.rb:13:in `loading'
	 7: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/concurrency/share_lock.rb:151:in `exclusive'
	 6: from /Users/pat/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/dependencies/interlock.rb:14:in `block in loading'
	 5: from /Users/pat/Code/tmp/hackweek/app/models/user.rb:1:in `<top (required)>'
	 4: from /Users/pat/Code/tmp/hackweek/app/models/user.rb:31:in `<class:User>'
	 3: from /Users/pat/Code/ruby/thinking-sphinx/lib/thinking_sphinx/callbacks.rb:10:in `append'
	 2: from /Users/pat/Code/ruby/thinking-sphinx/lib/thinking_sphinx/callbacks/appender.rb:5:in `call'
	 1: from /Users/pat/Code/ruby/thinking-sphinx/lib/thinking_sphinx/callbacks/appender.rb:16:in `call'
/Users/pat/Code/ruby/thinking-sphinx/lib/thinking_sphinx/callbacks/appender.rb:27:in `add_core_callbacks': uninitialized constant ThinkingSphinx::ActiveRecord (NameError)

… and from there, I found out that in Rails 5.2 (or at least, in this 5.2 app), Rails boot process has the following steps in this order:

1. Initialise railties/engines (e.g. Thinking Sphinx)
2. Fire the ActiveRecord load event (which invokes ActiveSupport.on_load(:active_record))
3. Fire the after_initialize event (which indicates everything in config/initializers has been loaded).

This is the order for both development and production environments.

In Rails 6.1, that order is the same in production, but in development, steps 2 and 3 are switched. And this is why it's related to #1199 and #1194 - the change in TS 5.2.1 was introduced while testing in Rails 6.1. @jdelStrother - sorry for looping you in again, but I'm curious as to which version of Rails you've been working with in relation to #1194?

I'm going to investigate a bit further, because I don't want to introduce a regression on the issue that Jonathan fixed. I'm not sure how much this is the case in a freshly-generated Rails app, versus something a bit more complex (such as this hackweek app, which uses Devise - and in the routes file, Devise loads the User model, which uses TS callbacks, which in turn use ThinkingSphinx::ActiveRecord). It could be that Thinking Sphinx needs to load that module at a later point than we first thought, just in case something like Devise is in play. I also suspect eager_load/cache_classes are a factor as well.

[pat]

So, further research, and I found that the switch of steps 2 and 3 above occur in all Rails versions since 4.2 (I checked 4.2, 5.1, 5.2, 6.0, 6.1). This means we can't rely on the order, so I've changed TS to ensure the ActiveRecord components are loaded at both of those steps.

I have also made a change to ensure app/indices is not part of the eager_load_paths in Rails versions prior to v6 (this was already the behaviour in v6). I'm pretty sure this was the cause of the exception you were seeing @hennevogel.

All of this is sorted in the develop branch via 241c43e - if anyone wants to test it themselves, that'd be great:

gem "thinking-sphinx",
  git: "https://github.com/pat/thinking-sphinx.git",
  branch: "develop"

… but either way, once the build passes, I'll get v5.2.2 released with the fixes.

[markkocera]

I can confirm the fixes work for me on Rails 6.1.4

[jdelStrother]

In Rails 6.1, that order is the same in production, but in development, steps 2 and 3 are switched. And this is why it's related to #1199 and #1194 - the change in TS 5.2.1 was introduced while testing in Rails 6.1. @jdelStrother - sorry for looping you in again, but I'm curious as to which version of Rails you've been working with in relation to #1194?

Yeah, 6.1 - but as you've noticed, Rails initialization is pretty weird in all versions. Your changes look good to me, though.

[hennevogel]

Running on develop (from just now) fixes it for me too.

Thanks for reporting this, and for having an app I can test it with

You can have more... 😉 Many Rails apps we use for producing SUSE are using your awesome code to be produtive @pat 💐

[pat]

Just released v5.3.0 with this fix!

And thanks Henne, great to know TS is used in plenty of SUSE's Rails apps 😊