Strange ActiveRecord error popping up

AdriSSSSn_De_la_Cru · October 17, 2006, 12:52am

Hello guys, I’m developing a new app in Rails, and every now and then
I get an ActiveRecord error, I cannot reproduce exactly what triggers
it, hope you can help me, or give me tips on debugging this kind of
stuff. This time I got the error reporting page, but normally I would
just see the 500.html page, with no info about what went wrong.

This is the error (it’s the complete text from the error page):

===============================================================
ActiveRecord::StatementInvalid in ShopController#new_order

Mysql::Error: Lost connection to MySQL server during query: UPDATE
sessions SET data =
‘BAh7BzoIYmFnbzoIQmFnCDoLQGl0ZW1zWwA6DUBpbnZvaWNlMDoMQGNsaWVu\ndDAiCmZsYXNoSUM6J0FjdGlvbkNvbnRyb2xsZXI6OkZsYXNoOjpGbGFzaEhh\nc2h7AAY6CkB1c2VkewA=\n’,
session_id = ‘3b490c37bd1d8b9553807982b19e23bd’, updated_at =
‘2006-10-16 17:41:00’ WHERE id = 1

RAILS_ROOT: ./script/…/config/…
Application Trace | Framework Trace | Full Trace

#{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:122:in
log' #{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/connection_adapters/mysql_adapter.rb:224:inexecute’
#{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/connection_adapters/mysql_adapter.rb:239:in
update' #{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/base.rb:1781:inupdate_without_lock’
#{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/locking/optimistic.rb:60:in
update_without_callbacks' #{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/callbacks.rb:267:inupdate_without_timestamps’
#{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/timestamp.rb:48:in
update' #{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/base.rb:1774:increate_or_update_without_callbacks’
#{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/callbacks.rb:242:in
create_or_update' #{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/base.rb:1530:insave_without_validation’
#{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/validations.rb:749:in
save_without_transactions' #{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/transactions.rb:120:insave’
#{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:51:in
transaction' #{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/transactions.rb:86:intransaction’
#{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/transactions.rb:112:in
transaction' #{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/transactions.rb:120:insave’
#{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/session/active_record_store.rb:307:in
update' #{RAILS_ROOT}/vendor/rails/activerecord/lib/active_record/base.rb:863:insilence’
#{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/session/active_record_store.rb:307:in
update' #{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/session/active_record_store.rb:314:inclose’
c:/development/ruby/lib/ruby/1.8/cgi/session.rb:330:in close' #{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/base.rb:1155:inclose_session’
#{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/base.rb:1200:in
process_cleanup_without_flash' #{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/flash.rb:146:inprocess_cleanup_without_filters’
#{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/filters.rb:657:in
process_cleanup_without_session_management_support' #{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/session_management.rb:123:inprocess_cleanup_without_components’
#{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/components.rb:176:in
process_cleanup' #{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/base.rb:432:inprocess_without_filters’
#{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/filters.rb:620:in
process_without_session_management_support' #{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/session_management.rb:114:inprocess’
#{RAILS_ROOT}/vendor/rails/actionpack/lib/action_controller/base.rb:330:in
process' #{RAILS_ROOT}/vendor/rails/railties/lib/dispatcher.rb:41:indispatch’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel/rails.rb:73:in
process' c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:551:inprocess_client’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:550:in
process_client' c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:636:inrun’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:636:in
run' c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:625:inrun’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:956:in
run' c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:955:inrun’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/bin/mongrel_rails:127:in
run' c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel/command.rb:199:inrun’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/bin/mongrel_rails:235
#{RAILS_ROOT}/vendor/rails/activesupport/lib/active_support/dependencies.rb:357:in
load' #{RAILS_ROOT}/vendor/rails/railties/lib/commands/servers/mongrel.rb:48 c:/development/ruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:inrequire’
#{RAILS_ROOT}/vendor/rails/activesupport/lib/active_support/dependencies.rb:364:in
require' #{RAILS_ROOT}/vendor/rails/railties/lib/commands/server.rb:39 c:/development/ruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:inrequire’
script/server:3

Request

Parameters: None

Show session dump

:bag: !ruby/object:Bag
client:
invoice:
items: []

flash: !map:ActionController::Flash::FlashHash {}

Response
Headers: {“Status”=>“500 Internal Error”, “cookie”=>[],
“Content-Type”=>“text/html; charset=utf-8”,
“Cache-Control”=>“no-cache”}

===============================================================

Thanks in advance.
Adrián.

AdriSSSSn_De_la_Cru · October 17, 2006, 1:02am

A variety of things can cause this kind of thing, some of the possivle
causes are listed here
http://dev.mysql.com/doc/refman/5.0/en/gone-away.html
One that is particularly relevant in development mode is that mysql
might time out your database connections if you are inactive for too
long (whereas in the real worl you are far less likely to get no
activity for long periods of time).

Fred

AdriSSSSn_De_la_Cru · October 17, 2006, 1:20am

On 10/16/06, Fred [email protected] wrote:

Fred
That’s interesting. I had another thread the other day because in dev
mode
, if I let the app sit for a while, it takes forever (minutes) to
reload.
I thought the culprit was Ruby as I looked in Windows Task Manager and
saw
some high mem use. However , watching it for a few days the memory
hogging
wasn’t an issue. Generally I don’t lose the db connection but I wonder
if
my symptoms are connected.

Stuart

AdriSSSSn_De_la_Cru · October 17, 2006, 1:42am

Thanks for the link Fred,

The weirdest thing is that I get the same error with Sqlite3, and it
doesn’t use a client-server mode. In fact, I started getting that
error in Sqlite3, that’s why I moved to Mysql just to face the same
problem.

Any help you can lend me would be great guys.

Here is the error dump when it crashed on Sqlite3 (btw I’m using a
windowsBox, and edgeRails):

=============================================================
SQLite3::SQLException (SQL logic error or missing database):
c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/errors.rb:94:in
check' c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/resultset.rb:76:incheck’
c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/resultset.rb:68:in
commence' c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/resultset.rb:61:ininitialize’
c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/statement.rb:158:in
execute' c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/database.rb:211:inexecute’
c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/database.rb:186:in
prepare' c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/database.rb:210:inexecute’
c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/database.rb:587:in
transaction' /vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:179:inbegin_db_transaction’
/vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:341:in
catch_schema_changes' /vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:179:inbegin_db_transaction’
/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:48:in
transaction' /vendor/rails/activerecord/lib/active_record/transactions.rb:86:intransaction’
/vendor/rails/activerecord/lib/active_record/transactions.rb:112:in
transaction' /vendor/rails/activerecord/lib/active_record/transactions.rb:120:insave’
/vendor/rails/actionpack/lib/action_controller/session/active_record_store.rb:307:in
update' /vendor/rails/activerecord/lib/active_record/base.rb:863:insilence’
/vendor/rails/actionpack/lib/action_controller/session/active_record_store.rb:307:in
update' /vendor/rails/actionpack/lib/action_controller/session/active_record_store.rb:314:inclose’
c:/development/ruby/lib/ruby/1.8/cgi/session.rb:330:in close' /vendor/rails/actionpack/lib/action_controller/base.rb:1155:inclose_session’
/vendor/rails/actionpack/lib/action_controller/base.rb:1200:in
process_cleanup_without_flash' /vendor/rails/actionpack/lib/action_controller/flash.rb:146:inprocess_cleanup_without_filters’
/vendor/rails/actionpack/lib/action_controller/filters.rb:657:in
process_cleanup_without_session_management_support' /vendor/rails/actionpack/lib/action_controller/session_management.rb:123:inprocess_cleanup_without_components’
/vendor/rails/actionpack/lib/action_controller/components.rb:176:in
process_cleanup' /vendor/rails/actionpack/lib/action_controller/base.rb:432:inprocess_without_filters’
/vendor/rails/actionpack/lib/action_controller/filters.rb:620:in
process_without_session_management_support' /vendor/rails/actionpack/lib/action_controller/session_management.rb:114:inprocess’
/vendor/rails/actionpack/lib/action_controller/base.rb:330:in
process' /vendor/rails/railties/lib/dispatcher.rb:41:indispatch’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel/rails.rb:73:in
process' c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:551:inprocess_client’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:550:in
process_client' c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:636:inrun’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:636:in
run' c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:625:inrun’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:956:in
run' c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:955:inrun’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/bin/mongrel_rails:127:in
run' c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel/command.rb:199:inrun’
c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/bin/mongrel_rails:235
/vendor/rails/activesupport/lib/active_support/dependencies.rb:357:in
load' /vendor/rails/railties/lib/commands/servers/mongrel.rb:48 c:/development/ruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:inrequire’
/vendor/rails/activesupport/lib/active_support/dependencies.rb:364:in
require' /vendor/rails/railties/lib/commands/server.rb:39 c:/development/ruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:inrequire’
script/server:3

Rendering
./script/…/config/…/vendor/rails/actionpack/lib/action_controller/templates/rescues/layout.rhtml
(500 Internal Error)
SQL logic error or missing database

c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/errors.rb:94:in
`check’

c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/resultset.rb:76:in
`check’

c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/resultset.rb:68:in
`commence’

c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/resultset.rb:61:in
`initialize’

c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/statement.rb:158:in
`execute’

c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/database.rb:211:in
`execute’

c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/database.rb:186:in
`prepare’

c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/database.rb:210:in
`execute’

c:/development/ruby/lib/ruby/gems/1.8/gems/sqlite3-ruby-1.1.0-mswin32/lib/sqlite3/database.rb:587:in
`transaction’

./script/…/config/…/vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:179:in
`begin_db_transaction’

./script/…/config/…/vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:341:in
`catch_schema_changes’

./script/…/config/…/vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:179:in
`begin_db_transaction’

./script/…/config/…/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:48:in
`transaction’

./script/…/config/…/vendor/rails/activerecord/lib/active_record/transactions.rb:86:in
`transaction’

./script/…/config/…/vendor/rails/activerecord/lib/active_record/transactions.rb:112:in
`transaction’

./script/…/config/…/vendor/rails/activerecord/lib/active_record/transactions.rb:120:in
`save’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/session/active_record_store.rb:307:in
`update’

./script/…/config/…/vendor/rails/activerecord/lib/active_record/base.rb:863:in
`silence’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/session/active_record_store.rb:307:in
`update’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/session/active_record_store.rb:314:in
`close’

c:/development/ruby/lib/ruby/1.8/cgi/session.rb:330:in `close’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/base.rb:1155:in
`close_session’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/base.rb:1200:in
`process_cleanup_without_flash’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/flash.rb:146:in
`process_cleanup_without_filters’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/filters.rb:657:in
`process_cleanup_without_session_management_support’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/session_management.rb:123:in
`process_cleanup_without_components’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/components.rb:176:in
`process_cleanup’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/base.rb:432:in
`process_without_filters’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/filters.rb:620:in
`process_without_session_management_support’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/session_management.rb:114:in
`process’

./script/…/config/…/vendor/rails/actionpack/lib/action_controller/base.rb:330:in
`process’

./script/…/config/…/vendor/rails/railties/lib/dispatcher.rb:41:in
`dispatch’

c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel/rails.rb:73:in
`process’

c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:551:in
`process_client’

c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:550:in
`process_client’

c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:636:in
`run’

c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:625:in
`run’

c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:956:in
`run’

c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel.rb:955:in
`run’

c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/bin/mongrel_rails:127:in
`run’

c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/lib/mongrel/command.rb:199:in
`run’

c:/development/ruby/lib/ruby/gems/1.8/gems/mongrel-0.3.13.3-mswin32/bin/mongrel_rails:235
./script/…/config/…/vendor/rails/activesupport/lib/active_support/dependencies.rb:357:in
`load’
./script/…/config/…/vendor/rails/railties/lib/commands/servers/mongrel.rb:48

c:/development/ruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in
require' ./script/../config/../vendor/rails/activesupport/lib/active_support/dependencies.rb:364:inrequire’
./script/…/config/…/vendor/rails/railties/lib/commands/server.rb:39

c:/development/ruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in
`require’
script/server:3

Strange ActiveRecord error popping up

c:/development/ruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `require’ script/server:3

c:/development/ruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in
`require’
script/server:3