ActiveSupport::BufferedLogger and us-ascii message on ruby 1.9.x

Yehuda katz has worked on encoding problem today. See http://github.com/rails/rails/commit/25215d7285db10e2c04d903f251b79... for example. Can you check if you have the problem before and/or after this commit?

I have the last HEAD of master and it does not work either.

I ran into this issue since I have a database in latin1

#config/database.yml

development:
  encoding: latin1
  # blabla ...

ruby $PATH_TO_RAILS3 c

u = User.new :name => 'Stéphane XXXX'

u.valid?

And then it raises this error

Encoding::UndefinedConversionError: "\xC3" from ASCII-8BIT to UTF-8
    from /home/hery/Software/rails/activesupport/lib/active_support/buffered_logger.rb:104:in `write'
    from /home/hery/Software/rails/activesupport/lib/active_support/buffered_logger.rb:104:in `block in flush'
    from <internal:prelude>:10:in `synchronize'
    from /home/hery/Software/rails/activesupport/lib/active_support/buffered_logger.rb:101:in `flush'
    from /home/hery/Software/rails/activesupport/lib/active_support/buffered_logger.rb:121:in `auto_flush'
    from /home/hery/Software/rails/activesupport/lib/active_support/buffered_logger.rb:66:in `add'
    from /home/hery/Software/rails/activesupport/lib/active_support/buffered_logger.rb:77:in `debug'
    from /home/hery/Software/rails/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:210:in `rescue in log'
    from /home/hery/Software/rails/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:201:in `log'
    from /home/hery/Software/rails/activerecord/lib/active_record/connection_adapters/mysql_adapter.rb:286:in `execute'
    from /home/hery/Software/rails/activerecord/lib/active_record/connection_adapters/mysql_adapter.rb:616:in `select'
    from /home/hery/Software/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:7:in `select_all'
    from /home/hery/Software/rails/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:56:in `select_all'
    from /home/hery/Software/rails/activerecord/lib/active_record/base.rb:427:in `find_by_sql'
    from /home/hery/Software/rails/activerecord/lib/active_record/relation.rb:63:in `to_a'
    from /home/hery/Software/rails/activerecord/lib/active_record/relation/finder_methods.rb:324:in `find_first'
... 4 levels...
    from /home/hery/Software/rails/activemodel/lib/active_model/validator.rb:151:in `each'
    from /home/hery/Software/rails/activemodel/lib/active_model/validator.rb:151:in `validate'
    from /home/hery/Software/rails/activesupport/lib/active_support/callbacks.rb:309:in `_callback_before_15'
    from /home/hery/Software/rails/activesupport/lib/active_support/callbacks.rb:419:in `_run_validate_callbacks'
    from /home/hery/Software/rails/activemodel/lib/active_model/validations.rb:201:in `run_validations!'
    from /home/hery/Software/rails/activemodel/lib/active_model/validations/callbacks.rb:53:in `block in run_validations!'
    from /home/hery/Software/rails/activesupport/lib/active_support/callbacks.rb:408:in `_run_validation_callbacks'
    from /home/hery/Software/rails/activemodel/lib/active_model/validations/callbacks.rb:53:in `run_validations!'
    from /home/hery/Software/rails/activemodel/lib/active_model/validations.rb:168:in `valid?'
    from /home/hery/Software/rails/activerecord/lib/active_record/validations.rb:55:in `valid?'
    from (irb):3
    from /home/hery/Software/rails/railties/lib/rails/commands/console.rb:47:in `start'
    from /home/hery/Software/rails/railties/lib/rails/commands/console.rb:8:in `start'
    from /home/hery/Software/rails/railties/lib/rails/commands.rb:23:in `<top (required)>'
    from script/rails:6:in `require'
    from script/rails:6:in `<main>'

I have attach a patch but does not know if it is (add some tests....)

@Hery: can you please give your output in console for this:

irb(main):001:0> __ENCODING__
=> #<Encoding:UTF-8>
irb(main):002:0> 'whatever'.encoding
=> #<Encoding:UTF-8>
irb(main):003:0> ENV['LC_CTYPE']
=> "UTF-8"

irb encoding seems to be determined by shell locale settings ($LC_CTYPE, etc)

And for "héhé".force_encoding 'us-ascii': Exception may be the correct behavior here. The string tagged with ascii contains non-ascii characters, doesn't it?

@serge

My encoding environment variables are right : I only use UTF-8
It's a problem with a database encoded in latin1 and logger (in ascii)

I use UTF-8 in my application project and have a database in latin1

The code above is just to show you how to reproduce this bug....

Application in UTF-8 and database in latin1 ...

>> __ENCODING__
=> #<Encoding:UTF-8>
>> 'whaterver'.encoding
=> #<Encoding:UTF-8>
>> ENV['LC_TYPE']
=> nil
8>

Thanks for the update, Hery! I tried to reproduce the bug with postgres DB with no luck. (I did create a database in latin1 and set up database.yml accordingly)

But your mysql backtrace is interesting, it looks like exception is raised in recuse block for another one. I wonder how interpolated message on line 209 of abstract_adapter.rb gets incorrect encoding tag. Will try to get mysql setup to find that out. What mysql connector gem and version are you using?

I think your logger should already be in UTF-8, one way to check is:

irb(main):011:0* ActiveRecord::Base.logger.instance_variable_get('@log').external_encoding
=> #<Encoding:UTF-8>
irb(main):012:0> ActiveRecord::Base.logger.instance_variable_get('@log').internal_encoding
=> nil

I have the same results

Do you have a validation field ?

I use database/tables in latin1 with mysql 5.1

You must create a model with a validates_uniqueness_of and test the validation with accentuated characters

I just tried this with a latin1 mysql db with a uniqueness validation; no issue.

From my logs:

  Category Load (0.4ms)  SELECT categories.id FROM categories
WHERE (categories.name = BINARY 'Stéphane XXXX') AND
(categories.project_id = 1) AND (categories.type IS NULL)
LIMIT 1

I'm not sure how to reproduce.

Doh! I was on Ruby 1.8. Reproduced on 1.9.2 :)

yep ruby 1.9.x :) I Just wrote that on my first thread ;)

Successfully reproduced this with mysql. To make the long story short, here's the distilled difference in behaviors of mysql and pg connection adapters:

mysql:

> User.connection.quote('Stéphane').encoding
=> #<Encoding:ASCII-8BIT>

pg:

> User.connection.quote('Stéphane').encoding
=> #<Encoding:ISO-8859-1>

I believe the root cause is in adapters' quote_string methods. Postgres adapter calls pg gem escape method which takes care of encodings:

pg.c around line 1375:

 * Encoding of escaped string will be equal to client encoding of connection.

and mysql obviously doesn't do that (or at least mysql 2.8.1 gem doesn't do that for me).

The workaround may be to make MysqlAdapter#quote_string look more like this:

      def quote_string(string)
        encoding = Encoding.find(@config[:encoding]) rescue nil
        encoded_string = encoding ? string.encode(encoding) : string
        quoted_string = @connection.quote(encoded_string)
        encoding ? quoted_string.force_encoding(encoding) : quoted_string
      end

With some extra care for making latin1 encoding alias or changing it to iso-8859-1 in database.yml.

But I wonder if the issue should really be addressed in mysql gem code.

Please find proposed patch based on the above. The database.yml should include another setting ruby_encoding: iso-8859-1 for the encoding: latin1 case. That's because I couldn't find any way to convince mysql to understand iso-8859-1 name, and at the same time I didn't find a way to dynamically add encoding aliases in ruby (1.9.1).

I understand that it's not the prettiest workaround, so I'm very open to suggestions. However the main question remains the same: is this encoding handling a responsibility of MysqlAdapter or mysql gem?

I really don't think this kind of mangling belongs in MysqlAdapter.
The mysql2 gem fixes the issue:

ruby-1.9.2-preview3 > User.connection.quote('Sebastián').encoding
=> #<Encoding:ISO-8859-1>

I haven't tested with mysqlplus, though.

Automatic cleanup of spam.