pat / thinking-sphinx

Sphinx/Manticore plugin for ActiveRecord/Rails
http://freelancing-gods.com/thinking-sphinx
MIT License
1.63k stars 470 forks source link

Rails 6 test issue #1195

Closed atomical closed 3 years ago

atomical commented 3 years ago
An error occurred in a `before(:suite)` hook.
Failure/Error: ThinkingSphinx::Test.start_with_autostop

Riddle::CommandFailedError:
  Sphinx command failed to execute

I'm seeing this after our Rails 6 upgrade. I'm wondering if this deprecation warning finally turned into an error?

https://github.com/pat/thinking-sphinx/issues/1165

pat commented 3 years ago

My initial guess is that the issues aren't related - I wouldn't expect callbacks to be involved when starting Sphinx.

Is this issue just in the test environment? i.e. do TS/Sphinx work fine in dev (i.e. using the standard rake tasks, etc)?

atomical commented 3 years ago

It's just in the test environment. Starting sphinx in development works. I just rebuilt and got some errors:

ERROR: index 'wireless_module_core': sql_range_query: Unknown column 'pcms_wireless_modules.id' in 'field list'

wireless module model has:

  has_one :pcm

There isn't a pcms_wireless_modules table. I'm looking to see if there was a change to has_one in rails 6.

pat commented 3 years ago

What does the index definition for the WirelessModule model look like?

atomical commented 3 years ago
has pcm(:id), as: :pcm_id
has pcm(:serial_number), as: :pcm
pat commented 3 years ago

Hmm… I've no idea if this is related, and the syntax you've got should still work. But also, you can use the method notation rather than arguments without any issues (it was only a problem back before TS v3 and MRI 1.9):

has pcm.id, as: :pcm_id
has pcm.serial_number, as: :pcm
atomical commented 3 years ago

Tried that in no luck. I commented out the offending lines in the indexes but I'm still seeing the error in rspec unfortunately.

atomical commented 3 years ago

Weird, when I'm running rake db:test:prepare I'm getting:

ActiveRecord::StatementInvalid: Mysql2::Error: Row size too large. The maximum row size for the used table type, not counting BLOBs, is 65535. This includes storage overhead, check the manual. You have to change some columns to TEXT or BLOBs
atomical commented 3 years ago
<Riddle::CommandResult:0x00007fb5d0dd0580 @output="Sphinx 2.2.11-id64-release (95ae9a6)\nCopyright (c) 2001-2016, Andrew Aksyonoff\nCopyright (c) 2008-2016, Sphinx Technologies Inc (http://sphinxsearch.com)\n\nusing config file 'config/test.sphinx.conf'...\nERROR: section 'activation_description_core_0' (type='source') already exists in config/test.sphinx.conf line 5670 col 1.\nFATAL: failed to parse config file 'config/test.sphinx.conf'\n", @status=1, @command="indexer --config \"config/test.sphinx.conf\" --all", @successful=false>
atomical commented 3 years ago

I had to comment out some indexes. And fix some other issues. I'll follow up when I'm more sure about the cause.

pat commented 3 years ago
ERROR: section 'activation_description_core_0' (type='source') already exists in config/test.sphinx.conf

This part of the output you shared makes me wonder if it's actually the same issue as #1191 - which I still haven't had the chance to look into deeply (sorry @thebravoman!). But it's good to know that this seems to have started with your Rails 6 upgrade, and it looks like you're perhaps both using SQL-backed indices rather than real-time indices (which is maybe why I've not seen it in my own apps, but helps narrow down the focus).

Something seems to be evaluating index definitions multiple times… no idea if it's thread-related. Perhaps that helps your own debugging, but I'll try to get a test app set up soon and see if I can reproduce with SQL-backed indices + Rails 6 + test environment.

thebravoman commented 3 years ago

My offer for reproducing it on my machine and getting together over a video call still stands, if this could help you narrow It down.

On Tue, Jun 8, 2021, 07:42 Pat Allan @.***> wrote:

ERROR: section 'activation_description_core_0' (type='source') already exists in config/test.sphinx.conf

This part of the output you shared makes me wonder if it's actually the same issue as #1191 https://github.com/pat/thinking-sphinx/issues/1191

  • which I still haven't had the chance to look into deeply (sorry @thebravoman https://github.com/thebravoman!). But it's good to know that this seems to have started with your Rails 6 upgrade, and it looks like you're perhaps both using SQL-backed indices rather than real-time indices (which is maybe why I've not seen it in my own apps, but helps narrow down the focus).

Something seems to be evaluating index definitions multiple times… no idea if it's thread-related. Perhaps that helps your own debugging, but I'll try to get a test app set up soon and see if I can reproduce with SQL-backed indices + Rails 6 + test environment.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/pat/thinking-sphinx/issues/1195#issuecomment-856434231, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAKAGBOYX7ZFQRGJ7GYT5ADTRWNTLANCNFSM4546YFJA .

pat commented 3 years ago

Appreciated! Let me try and reproduce within a test app first - I'm hoping that would at least help give me a bit more context so any video calls are more productive :)

pat commented 3 years ago

Just thought of another question for you both: are you using the old-style classic loader, or Zeitwork's new approach?

pat commented 3 years ago

Oh, and: how are your index files named? e.g. app/indices/article_index.rb containing the index for the Article model - or a different pattern?

atomical commented 3 years ago

Oh, and: how are your index files named? e.g. app/indices/article_index.rb containing the index for the Article model - or a different pattern?

Exactly that.

atomical commented 3 years ago

I commented out a line in our code that calls ThinkingSphinx::Configuration.instance.indices thinking maybe it could be responsible. No luck. I'll keep working with it.

I also added a puts "ABC" in one of our indexes. It's being loaded twice. I'm going to check the configuration files and see if we're doing anything we shouldn't be in rails 6. Autoload maybe? Hrm.

pat commented 3 years ago

If you feel comfortable diving into the TS code: it might be worth looking at how the preload_indices and preload_index methods are behaving.

And I'm not sure if it's related, but the mutex (since Rails 5.1.5) is not a standard Ruby one, but rather something custom for Rails/Active Suppoort, that permits dependency loading while locked (see #1132).

With both of those things in mind, I'm wondering if shifting @preloaded_indices = true from line 96 up to 88 could help? Thus even if preload_indices is being invoked more than once, the second call should stop at the boolean check on line 87. Also, maybe within that method it's worth resetting the sources/indices (which are initially set in the superclass, Riddle::Configuration)… so:

def preload_indices
  @@mutex.synchronize do
    return if @preloaded_indices
    @preloaded_indices = true

    @indices = []
    @sources = []

    index_paths.each do |path|
      Dir["#{path}/**/*.rb"].sort.each { |file| preload_index file }
    end

    normalise
    verify
  end
end

(For what it's worth: I tried creating a sample app using Rails 6 and SQL-backed indices, and the super simple test suite was fine… also: it's interesting to note that this sounds like it's a consistent problem for @atomical, but intermittent for @thebravoman 🤔 - I'm really hoping it's the same cause though!)

thebravoman commented 3 years ago

are you using the old-style classic loader, or Zeitwork's new approach?

config/application.rb:    config.autoloader = :classic

how are your index files named? e.g. app/indices/article_index.rb containing the index for the Article model - or a different pattern?

The model is app/models/course.rb

$ tree app/indices/
app/indices/
├── course_index.rb
atomical commented 3 years ago

It loads the indexes twice when config.eager_load = true in config/environments/test.rb

What I mean by that is if I put a puts statement in one of the index files it prints twice. And then I get an error for duplicate index in the configuration file.

I put a debugger statement in preload_indices and it's only being called once. Which is strange.

atomical commented 3 years ago

Should an index file be require'd by Rails before Sphinx loads it with preload_index()? Would that be a problem?

atomical commented 3 years ago

@thebravoman Try modifying this method in lib/thinking_sphinx/configuration.rb

  def preload_index(file)
    return if ActiveSupport::Dependencies.loaded.include?(file.split(".rb").first)
    if ActiveRecord::VERSION::MAJOR <= 5
      ActiveSupport::Dependencies.require_or_load file
    else
      load file
    end
  end

I think I've got it working.

pat commented 3 years ago

Thanks so much for that debugging! With those clues, I was able to reproduce the problem in my test app, with eager_load set to true and using the classic autoloader (either scenario separately is fine, though).

The fix I've added to my test app is putting the following line in config/application.rb:

config.eager_load_paths.reject! { |path| path == Rails.root.join("app", "indices").to_s }

I'll look into making Thinking Sphinx do this automatically (and thus, we don't need that check against which files are loaded).

@thebravoman: would love to know if this also fixes things for you? The fact that your issue has been intermittent makes me unsure if this is the exact same issue, but perhaps it's related?

thebravoman commented 3 years ago

Thanks @pat

$ bin/rspec spec/system/search_spec.rb 

/search
    search doesn't show content that has no image

Finished in 3.62 seconds (files took 0.9671 seconds to load)
1 example, 0 failures

Tests passed on my side. My current rails is 6.1 just to let you know.

pat commented 3 years ago

Just pushed a fix via 02bbb5071482cab8c91b956d2f6437b4cded3cce - if either/both of you are able to confirm the latest in develop works well in your apps, that'd be great, and I'll get a new release cut shortly.

gem "thinking-sphinx",
  :git    => "https://github.com/pat/thinking-sphinx.git",
  :branch => "develop"
thebravoman commented 3 years ago

All good on my side.

The gitrepo has a typo - it should be thinking-sphinx and not thinking-sphinix.

pat commented 3 years ago

My laptop keyboard is a little flaky :/ fixed - and especially, thank you for testing!

thebravoman commented 3 years ago

I just thought of something.

I have a rails engine and it is located in

gems/my-engine/

There I have a model

gems/my-engine/app/models/user.rb

Currently my indices are in

app/indices/user_index.rb

but I would like to move them to

gems/my-engine/app/indices/user_index.rb

My point is - is it possible to have inidices in many folders, not only app/indices but also gems/my-engine/app/indices and if it is should this be taken into account with the recent change?

pat commented 3 years ago

Indices in engines should get picked up automatically, provided they're in the engine's app/indices folder. If you find that's not the case, happy to discuss further, but perhaps in a separate issue :)

thebravoman commented 3 years ago

Of course. I will try it and if there are issues I will open a separate issue here. I just wanted to make sure the case of engines (as it is supported) is not forgotten with this change.

pat commented 3 years ago

Ah… I guess that depends on whether Rails adds an engine's app/* directories to eager_load_paths 🤔 I look forward to hearing what you discover!

pat commented 3 years ago

Just released v5.2.0 which includes this fix (and a further improvement that should ensure engine app/indices paths are also removed from eager_load_paths). So, I think this issue is all resolved - certainly, feel free to re-open the issue if I've got that wrong!