I'm sure I'm unique in this but I have a Rails 4.1.8 app running Tiny Tds / activerecord-sqlserver-adapter to MS SQL Server.
Upon calling /oauth/token it's generating an error: Cannot insert duplicate key row in object dbo.oauth_access_tokens with unique index index_oauth_access_tokens_on_refresh_token
Why would it be trying to insert a new record instead of updating it? I've tried to debug Doorkeeper by cloning the project and looking to find out why or how this is happening but I'm not having any luck.
Here is the information I do know: I'm running Rails 4.1.8, 2.0.0.rc2 (i've tried other versions to no avail), and Devise.
Upon sending an oauth2.password.client request the first time I get a successful token record created.
Upon the second request, I get a duplicate unique index key error from Tiny Tds.
Does anyone have experience with doorkeeper and could potentially point me in the right direction as to where to look for debugging this functionality. Everytime I think I find it, I try to see if I'm in the right spot and nothing is changing.
Here is log for the request:
Started POST "/oauth/token" for 127.0.0.1 at 2014-12-12 08:47:58 -0500
SQL (1.8ms) USE [CCPD_PROD]
ActiveRecord::SchemaMigration Load (2.3ms) EXEC sp_executesql N'SELECT [schema_migrations].* FROM [schema_migrations]'
Processing by Doorkeeper::TokensController#create as HTML
Parameters: {"client_id"=>"45e62866b8b3efea6286796c9f71b2c4ac7c5cbad6f140bc59d3d7b09eb9ae16", "grant_type"=>"password", "password"=>"[FILTERED]", "client_secret"=>"cf6d22582403db29b598dbf8cc26c2784e6cadb76702273907ce198063c4b8d8", "username"=>"[email protected]"}
User Load (2.8ms) EXEC sp_executesql N'SELECT TOP (1) [users].* FROM [users] WHERE [users].[email] = N''[email protected]'' ORDER BY [users].[personid] ASC'
SQL (2.6ms) BEGIN TRANSACTION
SQL (2.1ms) EXEC sp_executesql N'UPDATE [users] SET [encrypted_password] = @0 WHERE [users].[personid] = 169841; SELECT @@ROWCOUNT AS AffectedRows', N'@0 nvarchar(255)', @0 = N'$2a$12$OjD6F1IBZh699LO/xk8kE.K3t/2dmnuI.0k3JamB6BYuQLfrkzLkG' [["encrypted_password", "$2a$12$OjD6F1IBZh699LO/xk8kE.K3t/2dmnuI.0k3JamB6BYuQLfrkzLkG"]]
SQL (2.7ms) COMMIT TRANSACTION
Doorkeeper::Application Load (2.0ms) EXEC sp_executesql N'SELECT TOP (1) [oauth_applications].* FROM [oauth_applications] WHERE [oauth_applications].[uid] = N''45e62866b8b3efea6286796c9f71b2c4ac7c5cbad6f140bc59d3d7b09eb9ae16'' AND [oauth_applications].[secret] = N''cf6d22582403db29b598dbf8cc26c2784e6cadb76702273907ce198063c4b8d8'''
SQL (1.7ms) BEGIN TRANSACTION
Doorkeeper::AccessToken Exists (3.3ms) EXEC sp_executesql N'SELECT TOP (1) 1 AS one FROM [oauth_access_tokens] WHERE [oauth_access_tokens].[token] = N''d41108ce73447b801df85c4ad2a56f858a450f80e62416a7f819d7ef14163e9c'' COLLATE Latin1_General_CS_AS_WS'
SQL (4.6ms) EXEC sp_executesql N'INSERT INTO [oauth_access_tokens] ([application_id], [created_at], [expires_in], [resource_owner_id], [scopes], [token]) OUTPUT inserted.id VALUES (@0, @1, @2, @3, @4, @5)', N'@0 int, @1 datetime, @2 int, @3 int, @4 nvarchar(255), @5 nvarchar(255)', @0 = 1, @1 = '2014-12-12T13:47:58.956', @2 = 7200, @3 = 169841, @4 = N'public', @5 = N'd41108ce73447b801df85c4ad2a56f858a450f80e62416a7f819d7ef14163e9c' [["application_id", 1], ["created_at", Fri, 12 Dec 2014 13:47:58 UTC +00:00], ["expires_in", 7200], ["resource_owner_id", 169841], ["scopes", "public"], ["token", "d41108ce73447b801df85c4ad2a56f858a450f80e62416a7f819d7ef14163e9c"]]
TinyTds::Error: Cannot insert duplicate key row in object 'dbo.oauth_access_tokens' with unique index 'index_oauth_access_tokens_on_refresh_token'.: EXEC sp_executesql N'INSERT INTO [oauth_access_tokens] ([application_id], [created_at], [expires_in], [resource_owner_id], [scopes], [token]) OUTPUT inserted.id VALUES (@0, @1, @2, @3, @4, @5)', N'@0 int, @1 datetime, @2 int, @3 int, @4 nvarchar(255), @5 nvarchar(255)', @0 = 1, @1 = '2014-12-12T13:47:58.956', @2 = 7200, @3 = 169841, @4 = N'public', @5 = N'd41108ce73447b801df85c4ad2a56f858a450f80e62416a7f819d7ef14163e9c'
SQL (1.6ms) IF @@TRANCOUNT > 0 ROLLBACK TRANSACTION
Completed 500 Internal Server Error in 486ms
ActiveRecord::RecordNotUnique (TinyTds::Error: Cannot insert duplicate key row in object 'dbo.oauth_access_tokens' with unique index 'index_oauth_access_tokens_on_refresh_token'.: EXEC sp_executesql N'INSERT INTO [oauth_access_tokens] ([application_id], [created_at], [expires_in], [resource_owner_id], [scopes], [token]) OUTPUT inserted.id VALUES (@0, @1, @2, @3, @4, @5)', N'@0 int, @1 datetime, @2 int, @3 int, @4 nvarchar(255), @5 nvarchar(255)', @0 = 1, @1 = '2014-12-12T13:47:58.956', @2 = 7200, @3 = 169841, @4 = N'public', @5 = N'd41108ce73447b801df85c4ad2a56f858a450f80e62416a7f819d7ef14163e9c'):
activerecord-sqlserver-adapter (4.1.0) lib/active_record/connection_adapters/sqlserver/database_statements.rb:423:in `each'
activerecord-sqlserver-adapter (4.1.0) lib/active_record/connection_adapters/sqlserver/database_statements.rb:423:in `handle_to_names_and_values_dblib'
activerecord-sqlserver-adapter (4.1.0) lib/active_record/connection_adapters/sqlserver/database_statements.rb:412:in `handle_to_names_and_values'
activerecord-sqlserver-adapter (4.1.0) lib/active_record/connection_adapters/sqlserver/database_statements.rb:385:in `_raw_select'
activerecord-sqlserver-adapter (4.1.0) lib/active_record/connection_adapters/sqlserver/database_statements.rb:380:in `block in raw_select'
activerecord (4.1.8) lib/active_record/connection_adapters/abstract_adapter.rb:373:in `block in log'
activesupport (4.1.8) lib/active_support/notifications/instrumenter.rb:20:in `instrument'
activerecord (4.1.8) lib/active_record/connection_adapters/abstract_adapter.rb:367:in `log'
activerecord-sqlserver-adapter (4.1.0) lib/active_record/connection_adapters/sqlserver/database_statements.rb:380:in `raw_select'
activerecord-sqlserver-adapter (4.1.0) lib/active_record/connection_adapters/sqlserver/database_statements.rb:363:in `do_exec_query'
activerecord-sqlserver-adapter (4.1.0) lib/active_record/connection_adapters/sqlserver/database_statements.rb:24:in `exec_query'
activerecord-sqlserver-adapter (4.1.0) lib/active_record/connection_adapters/sqlserver/database_statements.rb:30:in `exec_insert'
activerecord (4.1.8) lib/active_record/connection_adapters/abstract/database_statements.rb:95:in `insert'
activerecord (4.1.8) lib/active_record/connection_adapters/abstract/query_cache.rb:14:in `insert'
activerecord (4.1.8) lib/active_record/relation.rb:64:in `insert'
activerecord (4.1.8) lib/active_record/persistence.rb:503:in `_create_record'
activerecord (4.1.8) lib/active_record/attribute_methods/dirty.rb:87:in `_create_record'
activerecord (4.1.8) lib/active_record/callbacks.rb:306:in `block in _create_record'
activesupport (4.1.8) lib/active_support/callbacks.rb:82:in `run_callbacks'
activerecord (4.1.8) lib/active_record/callbacks.rb:306:in `_create_record'
activerecord (4.1.8) lib/active_record/timestamp.rb:57:in `_create_record'
activerecord (4.1.8) lib/active_record/persistence.rb:483:in `create_or_update'
activerecord (4.1.8) lib/active_record/callbacks.rb:302:in `block in create_or_update'
activesupport (4.1.8) lib/active_support/callbacks.rb:113:in `call'
activesupport (4.1.8) lib/active_support/callbacks.rb:113:in `call'
activesupport (4.1.8) lib/active_support/callbacks.rb:166:in `block in halting'
activesupport (4.1.8) lib/active_support/callbacks.rb:86:in `call'
activesupport (4.1.8) lib/active_support/callbacks.rb:86:in `run_callbacks'
activerecord (4.1.8) lib/active_record/callbacks.rb:302:in `create_or_update'
activerecord (4.1.8) lib/active_record/persistence.rb:125:in `save!'
activerecord (4.1.8) lib/active_record/validations.rb:57:in `save!'
activerecord (4.1.8) lib/active_record/attribute_methods/dirty.rb:29:in `save!'
activerecord (4.1.8) lib/active_record/transactions.rb:273:in `block in save!'
activerecord (4.1.8) lib/active_record/transactions.rb:329:in `block in with_transaction_returning_status'
activerecord (4.1.8) lib/active_record/connection_adapters/abstract/database_statements.rb:201:in `block in transaction'
activerecord (4.1.8) lib/active_record/connection_adapters/abstract/database_statements.rb:209:in `within_new_transaction'
activerecord (4.1.8) lib/active_record/connection_adapters/abstract/database_statements.rb:201:in `transaction'
activerecord (4.1.8) lib/active_record/transactions.rb:208:in `transaction'
activerecord (4.1.8) lib/active_record/transactions.rb:326:in `with_transaction_returning_status'
activerecord (4.1.8) lib/active_record/transactions.rb:273:in `save!'
activerecord (4.1.8) lib/active_record/validations.rb:41:in `create!'
/Users/Joshua/Projects/doorkeeper/lib/doorkeeper/models/access_token_mixin.rb:67:in `find_or_create_for'
/Users/Joshua/Projects/doorkeeper/lib/doorkeeper/oauth/request_concern.rb:33:in `find_or_create_access_token'
/Users/Joshua/Projects/doorkeeper/lib/doorkeeper/oauth/password_access_token_request.rb:31:in `before_successful_response'
/Users/Joshua/Projects/doorkeeper/lib/doorkeeper/oauth/request_concern.rb:7:in `authorize'
/Users/Joshua/Projects/doorkeeper/lib/doorkeeper/request/password.rb:19:in `authorize'
/Users/Joshua/Projects/doorkeeper/app/controllers/doorkeeper/tokens_controller.rb:4:in `create'
actionpack (4.1.8) lib/abstract_controller/base.rb:189:in `process_action'
actionpack (4.1.8) lib/action_controller/metal/instrumentation.rb:31:in `block in process_action'
activesupport (4.1.8) lib/active_support/notifications.rb:159:in `block in instrument'
activesupport (4.1.8) lib/active_support/notifications/instrumenter.rb:20:in `instrument'
activesupport (4.1.8) lib/active_support/notifications.rb:159:in `instrument'
actionpack (4.1.8) lib/action_controller/metal/instrumentation.rb:30:in `process_action'
actionpack (4.1.8) lib/action_controller/metal/rendering.rb:10:in `process_action'
actionpack (4.1.8) lib/abstract_controller/base.rb:136:in `process'
actionpack (4.1.8) lib/action_controller/metal.rb:196:in `dispatch'
actionpack (4.1.8) lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
actionpack (4.1.8) lib/action_controller/metal.rb:232:in `block in action'
actionpack (4.1.8) lib/action_dispatch/routing/route_set.rb:82:in `call'
actionpack (4.1.8) lib/action_dispatch/routing/route_set.rb:82:in `dispatch'
actionpack (4.1.8) lib/action_dispatch/routing/route_set.rb:50:in `call'
actionpack (4.1.8) lib/action_dispatch/journey/router.rb:73:in `block in call'
actionpack (4.1.8) lib/action_dispatch/journey/router.rb:59:in `each'
actionpack (4.1.8) lib/action_dispatch/journey/router.rb:59:in `call'
actionpack (4.1.8) lib/action_dispatch/routing/route_set.rb:678:in `call'
omniauth (1.2.2) lib/omniauth/strategy.rb:186:in `call!'
omniauth (1.2.2) lib/omniauth/strategy.rb:164:in `call'
omniauth (1.2.2) lib/omniauth/strategy.rb:186:in `call!'
omniauth (1.2.2) lib/omniauth/strategy.rb:164:in `call'
omniauth (1.2.2) lib/omniauth/builder.rb:59:in `call'
omniauth (1.2.2) lib/omniauth/strategy.rb:186:in `call!'
omniauth (1.2.2) lib/omniauth/strategy.rb:164:in `call'
omniauth (1.2.2) lib/omniauth/strategy.rb:186:in `call!'
omniauth (1.2.2) lib/omniauth/strategy.rb:164:in `call'
omniauth (1.2.2) lib/omniauth/builder.rb:59:in `call'
warden (1.2.3) lib/warden/manager.rb:35:in `block in call'
warden (1.2.3) lib/warden/manager.rb:34:in `catch'
warden (1.2.3) lib/warden/manager.rb:34:in `call'
rack (1.5.2) lib/rack/etag.rb:23:in `call'
rack (1.5.2) lib/rack/conditionalget.rb:35:in `call'
rack (1.5.2) lib/rack/head.rb:11:in `call'
actionpack (4.1.8) lib/action_dispatch/middleware/params_parser.rb:27:in `call'
actionpack (4.1.8) lib/action_dispatch/middleware/flash.rb:254:in `call'
rack (1.5.2) lib/rack/session/abstract/id.rb:225:in `context'
rack (1.5.2) lib/rack/session/abstract/id.rb:220:in `call'
actionpack (4.1.8) lib/action_dispatch/middleware/cookies.rb:560:in `call'
activerecord (4.1.8) lib/active_record/query_cache.rb:36:in `call'
activerecord (4.1.8) lib/active_record/connection_adapters/abstract/connection_pool.rb:621:in `call'
activerecord (4.1.8) lib/active_record/migration.rb:380:in `call'
actionpack (4.1.8) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
activesupport (4.1.8) lib/active_support/callbacks.rb:82:in `run_callbacks'
actionpack (4.1.8) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
actionpack (4.1.8) lib/action_dispatch/middleware/reloader.rb:73:in `call'
actionpack (4.1.8) lib/action_dispatch/middleware/remote_ip.rb:76:in `call'
actionpack (4.1.8) lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
actionpack (4.1.8) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
railties (4.1.8) lib/rails/rack/logger.rb:38:in `call_app'
railties (4.1.8) lib/rails/rack/logger.rb:20:in `block in call'
activesupport (4.1.8) lib/active_support/tagged_logging.rb:68:in `block in tagged'
activesupport (4.1.8) lib/active_support/tagged_logging.rb:26:in `tagged'
activesupport (4.1.8) lib/active_support/tagged_logging.rb:68:in `tagged'
railties (4.1.8) lib/rails/rack/logger.rb:20:in `call'
quiet_assets (1.0.3) lib/quiet_assets.rb:23:in `call_with_quiet_assets'
actionpack (4.1.8) lib/action_dispatch/middleware/request_id.rb:21:in `call'
rack (1.5.2) lib/rack/methodoverride.rb:21:in `call'
rack (1.5.2) lib/rack/runtime.rb:17:in `call'
activesupport (4.1.8) lib/active_support/cache/strategy/local_cache_middleware.rb:26:in `call'
rack (1.5.2) lib/rack/lock.rb:17:in `call'
actionpack (4.1.8) lib/action_dispatch/middleware/static.rb:84:in `call'
rack (1.5.2) lib/rack/sendfile.rb:112:in `call'
railties (4.1.8) lib/rails/engine.rb:514:in `call'
railties (4.1.8) lib/rails/application.rb:144:in `call'
/Users/Joshua/Library/Application Support/Pow/Versions/0.5.0/node_modules/nack/lib/nack/server.rb:155:in `handle'
/Users/Joshua/Library/Application Support/Pow/Versions/0.5.0/node_modules/nack/lib/nack/server.rb:109:in `rescue in block (2 levels) in start'
/Users/Joshua/Library/Application Support/Pow/Versions/0.5.0/node_modules/nack/lib/nack/server.rb:106:in `block (2 levels) in start'
/Users/Joshua/Library/Application Support/Pow/Versions/0.5.0/node_modules/nack/lib/nack/server.rb:96:in `each'
/Users/Joshua/Library/Application Support/Pow/Versions/0.5.0/node_modules/nack/lib/nack/server.rb:96:in `block in start'
/Users/Joshua/Library/Application Support/Pow/Versions/0.5.0/node_modules/nack/lib/nack/server.rb:76:in `loop'
/Users/Joshua/Library/Application Support/Pow/Versions/0.5.0/node_modules/nack/lib/nack/server.rb:76:in `start'
/Users/Joshua/Library/Application Support/Pow/Versions/0.5.0/node_modules/nack/lib/nack/server.rb:12:in `run'
/Users/Joshua/Library/Application Support/Pow/Versions/0.5.0/node_modules/nack/bin/nack_worker:4:in `<main>'
Rendered /Users/Joshua/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/templates/rescues/_source.erb (0.6ms)
Rendered /Users/Joshua/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb (1.7ms)
Rendered /Users/Joshua/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb (10.6ms)
Rendered /Users/Joshua/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/templates/rescues/diagnostics.erb within rescues/layout (34.5ms)
Also, if I remove the unique index, it creates a new token record each time I make a request... I would think this should update the existing one?
UPDATE 12/12/14 9:27AM
If I set reuse_access_token in the doorkeeper initializer it will work... but I assume once the token expires it is going to throw the same error... I guess this will at least get me by until I get a response of a possible way to fix this...
Well, this was definitely not an issue with oAuth2 or Doorkeeper but as expected it was caused by SQL Server. More specifically, SQL Server 2005 not allowing multiple NULL values on a unique index.
So for this particular situation, I found a workaround that solves the problem for me until I can get this database migrated to a different DBMS system.
I rolled back my database using:
$ rake db:rollbackI then modified the db migrate file for doorkeeper to reflect this:
This allows the Doorkeeper system to function as it was intended.