search

reidmorrison / rails_semantic_logger

Rails Semantic Logger replaces the Rails default logger with Semantic Logger
https://logger.rocketjob.io/rails
Apache License 2.0
320 stars 114 forks source link

DB Connection issues when this gem is installed (when running tests) #218

Closed fguillen closed 4 months ago

fguillen commented 4 months ago

Environment

ruby 3.1.1p18 rails (7.0.2.2) rails_semantic_logger (4.14.0) semantic_logger (4.15.0) puma (5.6.2) mysql2 (0.5.6)

Default configuration

Stack trace:

Error:
Front::ArticlesControllerTest#test_index:
ActiveRecord::ConnectionNotEstablished: MySQL client is not connected
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:151:in `_query'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:151:in `block in query'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:150:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:150:in `query'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:632:in `block (2 levels) in raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/dependencies/interlock.rb:41:in `permit_concurrent_loads'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:631:in `block in raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_adapter.rb:765:in `block in log'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_adapter.rb:756:in `log'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:630:in `raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/mysql/database_statements.rb:96:in `raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/mysql/database_statements.rb:47:in `execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:211:in `begin_db_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract/transaction.rb:207:in `materialize!'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract/transaction.rb:258:in `block in begin_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract/transaction.rb:234:in `begin_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract/database_statements.rb:324:in `begin_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/test_fixtures.rb:129:in `block in setup_fixtures'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/test_fixtures.rb:128:in `each'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/test_fixtures.rb:128:in `setup_fixtures'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/test_fixtures.rb:10:in `before_setup'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/testing/setup_and_teardown.rb:40:in `before_setup'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/railties-7.0.2.2/lib/rails/test_help.rb:41:in `before_setup'

Expected Behavior

No random connection issues when running tests I don't know if the connection errors are happening in production, I didn't put this version in production.

Actual Behavior

Randomg db connections issues. Sometimes is this lost connection issue but other times looks like the db schema is corrupted and start showing weird fields-missing errors.

Sometimes the connection gets hold, and the process stops until I cancel it

Sometimes is weird errors:

Error:
Front::ArticlesControllerTest#test_create_invalid:
ActiveRecord::RecordInvalid: Validation failed: Tag must exist
    test/test_helper.rb:37:in `setup_front_user'
    test/controllers/front/articles_controller_test.rb:5:in `setup
Error:
UUIDTest#test_on_create_initialize_uuid:
ActiveRecord::RecordInvalid: Validation failed: Tag must exist
    test/models/uuid_test.rb:29:in `block in test_on_create_initialize_uuid'
    test/models/uuid_test.rb:25:in `map'
    test/models/uuid_test.rb:25:in `test_on_create_initialize_uuid'
Failure:
Admin::AdminSessionsControllerTest#test_forgot_password_submit [/Users/fernando.guillen/Development/RailsSkeleton/test/controllers/admin/admin_sessions_controller_test.rb:80]:
Expected nil to not be nil.

Things that don't fail if the gem is not intalled

fguillen commented 4 months ago

Maybe you can reproduce it by cloning this repo and going to this commit:

This is what I get any time I run this test:

> rails test test/controllers/front/articles_controller_test.rb --seed 2574
Run options: --seed 2574

# Running:

..........E

Error:
Front::ArticlesControllerTest#test_edit_not_allowed:
ActiveRecord::ConnectionNotEstablished: MySQL client is not connected
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:151:in `_query'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:151:in `block in query'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:150:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:150:in `query'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:632:in `block (2 levels) in raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/dependencies/interlock.rb:41:in `permit_concurrent_loads'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:631:in `block in raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_adapter.rb:765:in `block in log'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_adapter.rb:756:in `log'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:630:in `raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/mysql/database_statements.rb:96:in `raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/mysql/database_statements.rb:47:in `execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:211:in `begin_db_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract/transaction.rb:207:in `materialize!'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract/transaction.rb:258:in `block in begin_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract/transaction.rb:234:in `begin_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/connection_adapters/abstract/database_statements.rb:324:in `begin_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/test_fixtures.rb:129:in `block in setup_fixtures'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/test_fixtures.rb:128:in `each'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/test_fixtures.rb:128:in `setup_fixtures'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.0.2.2/lib/active_record/test_fixtures.rb:10:in `before_setup'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.0.2.2/lib/active_support/testing/setup_and_teardown.rb:40:in `before_setup'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/railties-7.0.2.2/lib/rails/test_help.rb:41:in `before_setup'

rails test test/controllers/front/articles_controller_test.rb:135

.

Finished in 4.095238s, 2.9302 runs/s, 7.8140 assertions/s.
12 runs, 32 assertions, 0 failures, 1 errors, 0 skips

 ~/Development/RailsSkeleton | 2024-05-09_adding_telemetry !3 ....................................................................................... 9s | system node | 14:21:56 
> rails test test/controllers/front/articles_controller_test.rb --seed 2574
Run options: --seed 2574

# Running:

..........E

Error:
Front::ArticlesControllerTest#test_edit_not_allowed:
ActiveRecord::RecordInvalid: Validation failed: Tag must exist
    test/test_helper.rb:37:in `setup_front_user'
    test/controllers/front/articles_controller_test.rb:5:in `setup'

rails test test/controllers/front/articles_controller_test.rb:135

E

Error:
Front::ArticlesControllerTest#test_update_not_allowed:
ActiveRecord::RecordInvalid: Validation failed: Tag must exist
    test/test_helper.rb:37:in `setup_front_user'
    test/controllers/front/articles_controller_test.rb:5:in `setup'

rails test test/controllers/front/articles_controller_test.rb:150

Finished in 3.797634s, 3.1599 runs/s, 7.6363 assertions/s.
12 runs, 29 assertions, 0 failures, 2 errors, 0 skips

But there are sometimes other errors, sometimes none

I always get some error when I run rails test though

If deactivate the gem rails_semantic_logger no errors are shown

fguillen commented 4 months ago

I am sure it is an issue with the tests concurrency. I have updated the gems and deleted some I was not using:

The errors has changed to:

Error:
Front::ArticlesControllerTest#test_show:
RuntimeError: Wrapped undumpable exception for: ActiveRecord::StatementInvalid: Mysql2::Error: This connection is in use by: #<Fiber:0x00000001127b5490 (resumed)>
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:151:in `_query'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:151:in `block in query'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:150:in `handle_interrupt'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/mysql2-0.5.6/lib/mysql2/client.rb:150:in `query'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:100:in `block (2 levels) in raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.1.3.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:98:in `block in raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.1.3.2/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract_adapter.rb:1143:in `log'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:97:in `raw_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/database_statements.rb:521:in `internal_execute'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:237:in `begin_db_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/transaction.rb:373:in `materialize!'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/transaction.rb:449:in `block in begin_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.1.3.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/transaction.rb:416:in `begin_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/database_statements.rb:352:in `begin_transaction'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/test_fixtures.rb:149:in `block in setup_fixtures'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/test_fixtures.rb:148:in `each'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/test_fixtures.rb:148:in `setup_fixtures'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activerecord-7.1.3.2/lib/active_record/test_fixtures.rb:10:in `before_setup'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/activesupport-7.1.3.2/lib/active_support/testing/setup_and_teardown.rb:40:in `before_setup'
    /Users/me/.rbenv/versions/3.1.1/lib/ruby/gems/3.1.0/gems/railties-7.1.3.2/lib/rails/test_help.rb:40:in `before_setup'
fguillen commented 4 months ago

I was debugging this, and it looks like it is no directly related to this gem. Even if having it activated makes the error to happen more often. I am closing this issue.

fguillen commented 4 months ago

The problem was caused for using ActionController::TestCase, better go for ActionDispatch::IntegrationTest: