Open nimir opened 10 months ago
rosa
commented
9 months ago Hey @nimir, sorry for the trouble! Could you let me know the output from this in your MySQL console?
show global variables like 'max_connections';And could you also copy your database.yml configuration? (without passwords and that stuff, just the other parameters)
nimir
commented
9 months ago Not at all @rosa , and thank you and the team for the great work
mysql> show global variables like 'max_connections';
+-----------------+-------+
| Variable_name | Value |
+-----------------+-------+
| max_connections | 151 |
+-----------------+-------+
1 row in set (0.03 sec)My database.yml file:
default: &default
adapter: mysql2
pool: <%= ENV.fetch("RAILS_MAX_THREADS") { 5 } %>
username: REDACTED
password: REDACTED
collation: utf8mb4_unicode_ci
development:
<<: *default
database: dmydb_development
test:
<<: *default
database: mydb_test
production:
<<: *default
host: <%= ENV["PRODUCTION_DB_HOST"] %>
database: mydb_production
username: <%= ENV["PRODUCTION_DB_USER"] %>
password: <%= ENV["PRODUCTION_DB_PASSWORD"] %>Interacting with the database works fine via the rails console, also the same job is currently working using sidekiq.
rosa
commented
9 months ago So strange. I haven't been able to reproduce this with your same configuration (except I'm running MySQL 8 in Docker via the 8.0.31 image). I imagine it matches this, but what do you get for the following MySQL settings?
mysql> show global variables like 'net_read_timeout';
+------------------+-------+
| Variable_name | Value |
+------------------+-------+
| net_read_timeout | 30 |
+------------------+-------+
1 row in set (0.01 sec)
mysql> show global variables like 'net_write_timeout';
+-------------------+-------+
| Variable_name | Value |
+-------------------+-------+
| net_write_timeout | 60 |
+-------------------+-------+
1 row in set (0.01 sec)
mysql> show global variables like 'connect_timeout';
+-----------------+-------+
| Variable_name | Value |
+-----------------+-------+
| connect_timeout | 10 |
+-----------------+-------+
1 row in set (0.01 sec)Weird that I got same output:
mysql> show global variables like 'net_read_timeout';
+------------------+-------+
| Variable_name | Value |
+------------------+-------+
| net_read_timeout | 30 |
+------------------+-------+
1 row in set (0.07 sec)
mysql> show global variables like 'net_write_timeout';
+-------------------+-------+
| Variable_name | Value |
+-------------------+-------+
| net_write_timeout | 60 |
+-------------------+-------+
1 row in set (0.01 sec)
mysql> show global variables like 'connect_timeout';
+-----------------+-------+
| Variable_name | Value |
+-----------------+-------+
| connect_timeout | 10 |
+-----------------+-------+
1 row in set (0.00 sec)I can add more debug code to solid_queue if that can help but will need your input on where to put it in the gem files?
rosa
commented
9 months ago Thank you 🙏 Let's try to see if we get anything useful in the development logs. Could you clear your log/development.log file (just deleting it would do) and then run solid queue and enqueue the job, so that you get the failure and then check that log to see if there's anything useful there?
nimir
commented
9 months ago Ok, here is the fresh log file:
[ActiveJob] Enqueued Notifications::MailerJob (Job ID: 6d355475-26f4-4ed3-af32-9127e6632c81) to SolidQueue(dc_development_mailer) with arguments: #<GlobalID:0x000000012ee50798 @uri=#<URI::GID gid://damancash/Payment/9F8K24229SMW4C69>>, :successfull
[ActiveJob] ↳ (irb):1:in `<main>'
[ActiveJob] [Notifications::MailerJob] [6d355475-26f4-4ed3-af32-9127e6632c81] Performing Notifications::MailerJob (Job ID: 6d355475-26f4-4ed3-af32-9127e6632c81) from SolidQueue(dc_development_mailer) enqueued at 2024-01-08T09:56:55.285563000Z with arguments: #<GlobalID:0x00000001350f8328 @uri=#<URI::GID gid://damancash/Payment/9F8K24229SMW4C69>>, :successfull
[ActiveJob] [Notifications::MailerJob] [6d355475-26f4-4ed3-af32-9127e6632c81] Performed Notifications::MailerJob (Job ID: 6d355475-26f4-4ed3-af32-9127e6632c81) from SolidQueue(dc_development_mailer) in 40.22msAhh, nothing useful there 😞 Thanks for trying that.
I imagine you got this after starting fresh, but just in case: do you get any errors when running
SolidQueue::Pause.all.pluck(:queue_name)
SolidQueue::ReadyExecution.where("queue_name LIKE ?", "dc_development_%").distinct(:queue_name).pluck(:queue_name)from your Rails console?
nimir
commented
9 months ago No errors
❯ rails c
Loading development environment (Rails 7.1.2)
irb(main):001> SolidQueue::Pause.all.pluck(:queue_name)
=> []
irb(main):002> SolidQueue::ReadyExecution.where("queue_name LIKE ?", "dc_development_%").distinct(:queue_name).pluck(:queue_name)
=> []Thanks for checking that 🙏 Ok, let's rule out forking here causing issues. Instead of starting Solid Queue via
bundle exec rake solid_queue:startcould you start just a single worker like this? In a Rails console:
worker = SolidQueue::Worker.new(polling_interval: 0.1, queues: "dc_development_*", threads: 2)
worker.startAnd then try enqueuing the job and see if you get the error.
To stop it, just do:
worker.stopYes, starting the worker without forking worked like a charm and I didn't get any errors.
❯ rails c
Loading development environment (Rails 7.1.2)
irb(main):001> worker = SolidQueue::Worker.new(polling_interval: 0.1, queues: "dc_development_*", threads: 2)
irb(main):002> worker.start
[SolidQueue] Starting Worker(pid=66198, hostname=Mohameds-MacBook-Pro-2.local, metadata={:polling_interval=>0.1, :queues=>"dc_development_*", :thread_pool_size=>2})
=> #<Thread:0x000000012f69fe58 /Users/nimir/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_queue-0.1.2/lib/solid_queue/processes/runnable.rb:37 run>
irb(main):003> Notifications::MailerJob.perform_later(Payment.last, :successfull)
[SolidQueue] Enqueued job {:queue_name=>"dc_development_mailer", :active_job_id=>"5673fe6f-c9fc-4d05-858c-475e03e60daa", :priority=>nil, :scheduled_at=>Mon, 08 Jan 2024 20:29:55.826036000 EET +02:00, :class_name=>"Notifications::MailerJob", :arguments=>{"job_class"=>"Notifications::MailerJob", "job_id"=>"5673fe6f-c9fc-4d05-858c-475e03e60daa", "provider_job_id"=>nil, "queue_name"=>"dc_development_mailer", "priority"=>nil, "arguments"=>[{"_aj_globalid"=>"gid://dc/Payment/9F8K24229SMW4C69"}, {"_aj_serialized"=>"ActiveJob::Serializers::SymbolSerializer", "value"=>"successfull"}], "executions"=>0, "exception_executions"=>{}, "locale"=>"en", "timezone"=>"Cairo", "enqueued_at"=>"2024-01-08T18:29:55.826241000Z", "scheduled_at"=>nil}, :concurrency_key=>nil}
Enqueued Notifications::MailerJob (Job ID: 5673fe6f-c9fc-4d05-858c-475e03e60daa) to SolidQueue(dc_development_mailer) with arguments: #<GlobalID:0x000000012f453500 @uri=#<URI::GID gid://dc/Payment/9F8K24229SMW4C69>>, :successfull
↳ (irb):3:in `<main>'
=>
<<REDACTED_JOB_DETAILS_INCLDUNG_SENSETIVE_INFO>>
:[SolidQueue] Claimed 1 jobs
Performing Notifications::MailerJob (Job ID: 5673fe6f-c9fc-4d05-858c-475e03e60daa) from SolidQueue(dc_development_mailer) enqueued at 2024-01-08T18:29:55.826241000Z with arguments: #<GlobalID:0x000000013c5d1410 @uri=#<URI::GID gid://dc/Payment/9F8K24229SMW4C69>>, :successfull
Performed Notifications::MailerJob (Job ID: 5673fe6f-c9fc-4d05-858c-475e03e60daa) from SolidQueue(dc_development_mailer) in 3.7ms
irb(main):004> worker.stop
=> #<Thread:0x000000012f69fe58 /Users/nimir/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_queue-0.1.2/lib/solid_queue/processes/runnable.rb:37 dead>So, how can we debug the forking part to get more useful insight on the cause?
rosa
commented
9 months ago Hey @nimir! So sorry for the silence and delay in replying after your last comment. I tried to come up with a good way to debug this but in the end, I had to work on other unrelated stuff and lost track of it. I'm quite puzzled about why this might be happening. Did you figure anything else on your own or are you still having the exact same problem?
nimir
commented
9 months ago Hi @rosa , no worries and I appreciate your support
I thought the issue might be with my version of MySQL so tried downgrading to v8.0 and also testing on fresh apps just to eliminate the possibility I am making something wrong in the configurations but I had no luck. Unfortunately I have limited time to work on this at the time!
hahwul
commented
9 months ago Hi @rosa
I'm using AWS RDS and I'm experiencing the same issue. The version is also similar 😭
The connection error appears after restarting fork occurs several times.
[SolidQueue] Restarting fork[71885] (status: )
[SolidQueue] Starting Worker(pid=71887, hostname=******, metadata={:polling_interval=>0.1, :queues=>"*", :thread_pool_size=>5})
[SolidQueue] Restarting fork[71887] (status: )
[SolidQueue] Starting Worker(pid=71993, hostname=******, metadata={:polling_interval=>0.1, :queues=>"*", :thread_pool_size=>5})
[SolidQueue] Restarting fork[71993] (status: )
[SolidQueue] Starting Worker(pid=71994, hostname=******, metadata={:polling_interval=>0.1, :queues=>"*", :thread_pool_size=>5})
/Users/user/.rvm/gems/ruby-3.3.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `_query': Mysql2::Error::ConnectionError: Lost connection to MySQL server during query (ActiveRecord::ConnectionFailed)
from /Users/user/.rvm/gems/ruby-3.3.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `block in query'
from /Users/user/.rvm/gems/ruby-3.3.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `handle_interrupt'
from /Users/user/.rvm/gems/ruby-3.3.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `query'
``I found a work around this morning but I am not sure how sustainable it is since it gives a depreciation warning
Setting reconnect: true in database.yaml
I don't get the connection lost error but i get this warning since this flag seems to be deprecated
WARNING: MYSQL_OPT_RECONNECT is deprecated and will be removed in a future version.The reconnect: true work around fails when I am enqueuing a job from another job and I get the lost mysql connection error again! 😢
Update: I am starting to think that work around didn't work at all and it was just some inconsistency !
rounders
commented
9 months ago Decided to give solid_queue a try today and I'm running into the same issue that @nimir described.
Ruby 3.2.2 MySQL: 8.2.0 (Homebrew) MySQL Adapter: mysql2 V0.5.5 Rails 7.1.2 Solid-Queue 0.1.2
[SolidQueue] Starting Dispatcher(pid=61704, hostname=fh-imac-2.local, metadata={:polling_interval=>1, :batch_size=>500})
[SolidQueue] Starting Worker(pid=61705, hostname=fh-imac-2.local, metadata={:polling_interval=>0.1, :queues=>"*", :thread_pool_size=>5})
/Users/rounders/.rvm/gems/ruby-3.2.2/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `_query': Mysql2::Error::ConnectionError: Lost connection to MySQL server during query (ActiveRecord::ConnectionFailed)
from /Users/rounders/.rvm/gems/ruby-3.2.2/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `block in query'
from /Users/rounders/.rvm/gems/ruby-3.2.2/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `handle_interrupt'
from /Users/rounders/.rvm/gems/ruby-3.2.2/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `query'Looking at my development.log file I can see that I get about 200 SolidQueue::ReadyExecution Pluck commands after starting solid_queue (using 'bundle exec rake solid_queue:start') before I see the first Mysql2::Error::ConnectionError error.
hahwul
commented
9 months ago Yesterday, I also conducted some tests. In my case, when I extended the worker's polling interval period to seconds, the issue did not occur. I'm not sure of the exact cause, but I hope this helps someone :D
development:
dispatchers:
- polling_interval: 1
batch_size: 500
workers:
- queues: "dc_development_*"
threads: 2
processes: 1
polling_interval: 1 # ⬅️ 0.1 to 1I think, It seems like there might be a key of solution in the MySQL connection settings and the access method of solid_queue.
nimir
commented
9 months ago @hahwul thanks for sharing the workaround, unfortunately it didn't work for me ... It just delays the error due to the extended polling interval i suppose!
gkeswani92
commented
9 months ago Experiencing something similar on ruby 3.2.2 and rails 7.1.3 with all of the above pointers tried
11:51:50 solid_queue.1 | /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `_query': Lost connection to MySQL server during query (Mysql2::Error::ConnectionError)
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `block in query'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `handle_interrupt'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `query'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/mysql2/database_statements.rb:100:in `block (2 levels) in raw_execute'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/mysql2/database_statements.rb:98:in `block in raw_execute'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract_adapter.rb:1143:in `log'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/mysql2/database_statements.rb:97:in `raw_execute'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:233:in `execute_and_free'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/mysql2/database_statements.rb:23:in `internal_exec_query'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/database_statements.rb:630:in `select'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/database_statements.rb:71:in `select_all'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/query_cache.rb:115:in `select_all'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/mysql2/database_statements.rb:14:in `block in select_all'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
11:51:50 solid_queue.1 | from /Users/gaurav/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/mysql2/database_statements.rb:10:in `select_all'
jairovm
commented
9 months ago Just my two cents. I got this error on a M1 Pro machine, and this is what I did.
brew upgrade mysql, and it installed version 8.3.0.mysql2 gem and decided to give trilogy adapter a try. You can see some interesting things here https://dev.to/justthev/benchmarking-trilogy-is-it-really-the-future-of-rails--3negThere are no more connection issues now. 🚀
bmb1603
commented
8 months ago Is there any fix yet? @rosa this seems to happen when starting solid queue but there are no Jobs or too few (< 5) Jobs to claim
rosa
commented
8 months ago I haven't been able to reproduce this in any way, @brincau, so no, I don't have a fix for it, I'm afraid.
mountaindog
commented
8 months ago I've seen the same thing: starting a solid queue is fine, but when running a rake command, it generates a MySQL connection error. The Trilogy adaptor seems to work better, but it has some issues when running GitHub Actions.
[SolidQueue] Starting Dispatcher(pid=35671, hostname=xxxxx-mac1.localdomain, metadata={:polling_interval=>1, :batch_size=>500})
[SolidQueue] Starting Worker(pid=35672, hostname=xxxxx-mac1.localdomain, metadata={:polling_interval=>0.1, :queues=>"*", :thread_pool_size=>5})
/Users/xxxxxx/.asdf/installs/ruby/3.3.0/lib/ruby/gems/3.3.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:151:in `_query': Mysql2::Error::ConnectionError: Lost connection to MySQL server during query (ActiveRecord::ConnectionFailed)
bendangelo
commented
4 months ago I suggest you just use the Trilogy gem. It fixed this issue for me.
Env and Versions:
3.3.08.2.0 for macos13.5 on arm64 (Homebrew)mysql2 V0.5.57.1.20.1.2Solid_Queue Configurations:
config/solid_queue.yml:Steps to reproduce:
Solid_Queue Log Trace: