Errno::EPIPE in Mysql::Protocol.write

[julian7]

When I try to connect to a rails app after a while (no other users, using rails 2.3.5, unicorn, ruby-mysql, with mysql server version 5.1.41 using tcp sockets), the first heartbeat (active? call from ActiveRecord's mysql adapter) runs into a broken pipe error.

I haven't found yet why TCPSocket#flush returns EPIPE on FreeBSD, but nevertheless it would be great to have a graceful handling of this error too.

Here's the backtrace:

[GEM_ROOT]/gems/ruby-mysql-2.9.2/lib/mysql/protocol.rb:617:in `flush'
[GEM_ROOT]/gems/ruby-mysql-2.9.2/lib/mysql/protocol.rb:617:in `block in write'
/usr/local/lib/ruby/1.9/timeout.rb:44:in `timeout'
[GEM_ROOT]/gems/ruby-mysql-2.9.2/lib/mysql/protocol.rb:616:in `write'
[GEM_ROOT]/gems/ruby-mysql-2.9.2/lib/mysql/protocol.rb:640:in `block in simple_command'
[GEM_ROOT]/gems/ruby-mysql-2.9.2/lib/mysql/protocol.rb:545:in `synchronize'
[GEM_ROOT]/gems/ruby-mysql-2.9.2/lib/mysql/protocol.rb:638:in `simple_command'
[GEM_ROOT]/gems/ruby-mysql-2.9.2/lib/mysql/protocol.rb:413:in `statistics_command'
[GEM_ROOT]/gems/ruby-mysql-2.9.2/lib/mysql.rb:502:in `stat'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/mysql_adapter.rb:277:in `active?'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract_adapter.rb:150:in `verify!'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:256:in `checkout_and_verify'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:252:in `checkout_existing_connection'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:186:in `block (2 levels) in checkout'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:184:in `loop'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:184:in `block in checkout'
/usr/local/lib/ruby/1.9/monitor.rb:190:in `mon_synchronize'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:183:in `checkout'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:98:in `connection'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:326:in `retrieve_connection'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_specification.rb:123:in `retrieve_connection'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_specification.rb:115:in `connection'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/query_cache.rb:9:in `cache'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/query_cache.rb:28:in `call'
[GEM_ROOT]/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:361:in `call'
[GEM_ROOT]/gems/rack-1.0.1/lib/rack/static.rb:33:in `call'
[GEM_ROOT]/gems/rack-bug-0.2.1/lib/rack/bug/toolbar.rb:14:in `call'
[GEM_ROOT]/gems/rack-bug-0.2.1/lib/rack/bug/toolbar.rb:54:in `pass'
[GEM_ROOT]/gems/rack-bug-0.2.1/lib/rack/bug/toolbar.rb:49:in `call'
[GEM_ROOT]/gems/actionpack-2.3.5/lib/action_controller/string_coercion.rb:25:in `call'
[GEM_ROOT]/gems/rack-1.0.1/lib/rack/head.rb:9:in `call'
[GEM_ROOT]/gems/rack-1.0.1/lib/rack/methodoverride.rb:24:in `call'
[GEM_ROOT]/gems/actionpack-2.3.5/lib/action_controller/params_parser.rb:15:in `call'
[GEM_ROOT]/gems/actionpack-2.3.5/lib/action_controller/session/cookie_store.rb:93:in `call'
[GEM_ROOT]/gems/actionpack-2.3.5/lib/action_controller/failsafe.rb:26:in `call'
[GEM_ROOT]/gems/rack-1.0.1/lib/rack/lock.rb:11:in `block in call'
:
[GEM_ROOT]/gems/rack-1.0.1/lib/rack/lock.rb:11:in `call'
[GEM_ROOT]/gems/actionpack-2.3.5/lib/action_controller/dispatcher.rb:106:in `call'
[GEM_ROOT]/gems/rails-2.3.5/lib/rails/rack/static.rb:31:in `call'
[GEM_ROOT]/gems/rack-1.0.1/lib/rack/urlmap.rb:46:in `block in call'
[GEM_ROOT]/gems/rack-1.0.1/lib/rack/urlmap.rb:40:in `each'
[GEM_ROOT]/gems/rack-1.0.1/lib/rack/urlmap.rb:40:in `call'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:634:in `process_client'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:707:in `block in worker_loop'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:705:in `each'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:705:in `worker_loop'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:596:in `block (2 levels) in spawn_missing_workers'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:593:in `fork'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:593:in `block in spawn_missing_workers'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:589:in `each'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:589:in `spawn_missing_workers'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:603:in `maintain_worker_count'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:270:in `start'
[GEM_ROOT]/gems/unicorn-0.97.0/lib/unicorn.rb:29:in `run'
[GEM_ROOT]/gems/unicorn-0.97.0/bin/unicorn_rails:204:in `'
/usr/local/bin/unicorn_rails:19:in `load'
/usr/local/bin/unicorn_rails:19:in `'

and this is my rake gems output (version names added by me):

• [I] authlogic 2.1.3
  • [R] activesupport 2.3.5
• [I] cancan 1.0.2
• [I] workflow 0.3.0
• [I] haml 2.2.22
• [I] will_paginate 2.3.12
• [I] formtastic 0.9.8
  • [R] activesupport 2.3.5
  • [R] actionpack 2.3.5
• [I] tiny_mce 0.1.2
• [I] sqlite3-ruby 1.2.5
• [I] ruby-mysql 2.9.2
• [I] hoptoad_notifier 2.2.2
  • [R] activesupport 2.3.5
• [I] newrelic_rpm 2.10.6
• [I] rack-bug 0.2.1
• [I] inploy 1.4.1

I'm using unicorn 0.97.0 with ruby 1.9.1p376 built from FreeBSD ports tree.

[tmtm]

I edited description to put <pre>.

[tmtm]

It seems that the code use fork.
If same Mysql object is used multiple process via fork and one process call Mysql#close or exit process, other processes cannot use the connection.

Example:

$ ruby -rmysql -e 'm=Mysql.new("localhost","user","passwd"); fork{}; sleep 1; m.query("select 123").fetch_row'
-e:1:in `query': MySQL server has gone away (Mysql::Error)
    from -e:1

[julian7]

Yes, I'm using unicorn in a pre-forking way. It's not copy-on-write friendly, but I use the standard way to restart database connections:

preload_app true
before_fork do |server, worker|
  defined?(ActiveRecord::Base) and ActiveRecord::Base.connection.disconnect!
end

after_fork do |server, worker|
  defined?(ActiveRecord::Base) and ActiveRecord::Base.establish_connection
end

In theory it closes database connections before forking, and re-establishes them in children.

[julian7]

After re-reading your example, I found out that you get a standard Mysql::Error, and not Errno::EPIPE. Mysql::Error is handled by rails' mysql connection management, but there's a special case in ActiveRecord::ConnectionAdapters::MysqlAdapter#active? method, which explicitely states: "mysql-ruby doesn't raise an exception when stat fails", and tries to return with @connection.errno.zero?.

I think there're three possible solutions for this:

• rescue Errno in Mysql::Protocol#write , setting @last_error
• rescue Errno in Mysql::Protocol#write, raising a ProtocolError
• tune ActiveRecord's mysql adapter to allow Errno-type exceptions, because of this very flavor of mysql adapters do it.

I think the second one would be the best choice.