Throwing Mysql2::Error seemingly randomly

[danascheider]

This started happening when I was running my front-end integration tests against the test API. The entire suite passed, I committed it, I ran it again, and suddenly I began getting errors of this kind:

XMLHttpRequest cannot load http://api.canto-test.com:3000/users/1. Origin http://localhost is not allowed by Access-Control-Allow-Origin.

In some, but not all, cases, this caused the Cucumber tests to fail.

What is happening is not actually a CORS issue; the client interprets a 500 error as a CORS issue because the response does not include the appropriate CORS header. Checking the Thin log, I see this output:

2015-05-14 23:38:16 - Sequel::DatabaseError - Mysql2::Error: Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8_general_ci,COERCIBLE) for operation '=':
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/adapters/mysql2.rb:78:in `query'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/adapters/mysql2.rb:78:in`block in _execute'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/database/logging.rb:37:in `log_yield'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/adapters/mysql2.rb:78:in`_execute'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/adapters/shared/mysql_prepared_statements.rb:34:in `block in execute'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/database/connecting.rb:250:in`block in synchronize'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/connection_pool/threaded.rb:99:in `hold'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/database/connecting.rb:250:in`synchronize'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/adapters/shared/mysql_prepared_statements.rb:34:in `execute'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/dataset/actions.rb:921:in`execute'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/adapters/mysql2.rb:195:in `execute'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/adapters/mysql2.rb:154:in`fetch_rows'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/dataset/actions.rb:802:in `with_sql_each'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/dataset/actions.rb:812:in`with_sql_first'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/dataset/placeholder_literalizer.rb:148:in `first'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/model/base.rb:878:in`block in def_finder_method'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sequel-4.22.0/lib/sequel/model/base.rb:313:in `find'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/canto-0.0.1.alpha5/lib/helpers/authorization_helper.rb:143:in`valid_credentials?'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/canto-0.0.1.alpha5/lib/helpers/authorization_helper.rb:34:in `authorized?'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/canto-0.0.1.alpha5/lib/helpers/authorization_helper.rb:91:in`protect'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/canto-0.0.1.alpha5/lib/routes/filters.rb:41:in `block in proprietary_auth_filters'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in`call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in`[]'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in`catch'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:965:in`block in filter!'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:965:in `each'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:965:in`filter!'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1083:in `block in dispatch!'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in`block in invoke'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in`invoke'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in`block in call!'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in`catch'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in`call!'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/slogger-0.0.11/lib/slogger/request_logger.rb:25:in`call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-cors-0.4.0/lib/rack/cors.rb:80:in `call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in`call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in`call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in`call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-1.6.0/lib/rack/logger.rb:15:in`call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-1.6.0/lib/rack/commonlogger.rb:33:in `call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in`call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:211:in `call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-1.6.0/lib/rack/head.rb:13:in`call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in`call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in`block in call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in`call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rack-1.6.0/lib/rack/reloader.rb:44:in `call'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:86:in`block in pre_process'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:84:in `catch'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:84:in`pre_process'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:53:in `process'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:39:in`receive_data'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/eventmachine-1.0.7/lib/eventmachine.rb:187:in `run_machine'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/eventmachine-1.0.7/lib/eventmachine.rb:187:in`run'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/lib/thin/backends/base.rb:73:in `start'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/lib/thin/server.rb:162:in`start'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/lib/thin/controllers/controller.rb:87:in `start'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/lib/thin/runner.rb:200:in`run_command'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/lib/thin/runner.rb:156:in `run!'
        /home/dana/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/thin-1.6.3/bin/thin:6:in`<top (required)>'
        /home/dana/.rbenv/versions/2.2.2/bin/thin:23:in `load'
        /home/dana/.rbenv/versions/2.2.2/bin/thin:23:in`<main>'

The few lines in the trace that refer to the Canto gem at all point to the authorization helper and a filter that runs its code, in particular this line (`authorization_helper.rb`, line 143):

@auth.credentials.last == User.find(username: @auth.credentials.first).password

Presumably, the encoding of the credentials in the request is wrong, but I don't understand why this is suddenly failing when it was passing before. It is possible, even likely, this is an issue with the front end, but I'm still calling it a bug since it is throwing an internal server error I didn't expect to see.