This project is archived and is in readonly mode.

#5006 open
Hery

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

Reported by Hery | June 29th, 2010 @ 04:53 PM | in 3.0.6

Hi guys,
I am running ruby-1.9@HEAD and rails@master

To reproduce it :

  log = ActiveSupport::BufferedLogger.new('/tmp/toto.log')
  str = "héhé"
  str.force_encoding 'us-ascii'
  log.add 0, str
  Encoding::InvalidByteSequenceError: "\xC3" on US-ASCII
    from /home/ruby/Software/rails/activesupport/lib/active_support/buffered_logger.rb:104:in `write'
    from /home/ruby/Software/rails/activesupport/lib/active_support/buffered_logger.rb:104:in `block in flush'
    from <internal:prelude>:10:in `synchronize'
    from /home/ruby/Software/rails/activesupport/lib/active_support/buffered_logger.rb:101:in `flush'
    from /home/ruby/Software/rails/activesupport/lib/active_support/buffered_logger.rb:121:in `auto_flush'
    from /home/ruby/Software/rails/activesupport/lib/active_support/buffered_logger.rb:66:in `add'
    from (irb):7
    from /home/ruby/Software/rails/railties/lib/rails/commands/console.rb:47:in `start'
    from /home/ruby/Software/rails/railties/lib/rails/commands/console.rb:8:in `start'
    from /home/ruby/Software/rails/railties/lib/rails/commands.rb:23:in `<top (required)>'
    from script/rails:6:in `require'
    from script/rails:6:in `<main>'

I ran into this issue when I wanted to migrate my old project under rails 3.x :

  • I created a new project (rails new mediatec)
  • My database encoding is latin1 (database.yml => encoding:latin1)
  • Ran my tests and see errors
  • typed in console u = User.new :name => "Stéphane XXXX"; u.valid? and see the us-ascii / utf-8 conflict
  • There is a validation rule in my User class : validates :name, :presence => true, :uniqueness => true

Comments and changes to this ticket

  • Bruno Michel

    Bruno Michel June 29th, 2010 @ 09:44 PM

    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?

  • Hery

    Hery June 29th, 2010 @ 10:28 PM

    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....)

  • Jeremy Kemper

    Jeremy Kemper June 29th, 2010 @ 11:38 PM

    • Assigned user set to “Yehuda Katz (wycats)”
    • State changed from “new” to “open”
    • Milestone cleared.
    • Importance changed from “” to “Low”
  • Jeremy Kemper

    Jeremy Kemper June 29th, 2010 @ 11:38 PM

    • Importance changed from “Low” to “High”
  • Serge Balyuk

    Serge Balyuk July 4th, 2010 @ 07:00 PM

    @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?

  • Hery

    Hery July 4th, 2010 @ 07:23 PM

    @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>
    
  • Serge Balyuk

    Serge Balyuk July 4th, 2010 @ 10:13 PM

    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
    
  • Hery

    Hery July 4th, 2010 @ 11:08 PM

    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

  • Jeremy Kemper

    Jeremy Kemper July 4th, 2010 @ 11:23 PM

    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.

  • Jeremy Kemper

    Jeremy Kemper July 4th, 2010 @ 11:37 PM

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

  • Hery

    Hery July 4th, 2010 @ 11:41 PM

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

  • Serge Balyuk

    Serge Balyuk July 5th, 2010 @ 03:51 PM

    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.

  • Serge Balyuk

    Serge Balyuk July 6th, 2010 @ 05:03 PM

    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?

  • Sebastian A. Espindola

    Sebastian A. Espindola July 27th, 2010 @ 11:18 PM

    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.

  • Jeremy Kemper
  • Jeremy Kemper

    Jeremy Kemper October 15th, 2010 @ 11:01 PM

    • Milestone set to 3.0.2
  • Ryan Bigg

    Ryan Bigg October 19th, 2010 @ 08:35 AM

    Automatic cleanup of spam.

  • Santiago Pastorino
  • Santiago Pastorino
  • Santiago Pastorino

    Santiago Pastorino February 27th, 2011 @ 03:15 AM

    • Milestone changed from 3.0.5 to 3.0.6

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

<h2 style="font-size: 14px">Tickets have moved to Github</h2>

The new ticket tracker is available at <a href="https://github.com/rails/rails/issues">https://github.com/rails/rails/issues</a>

Pages