Discourse DB Error When Creating New Users via SSO Login

Summary

Discourse DB constraint error because of duplicate key values generated when users without an account attempt to log in via SSO. Causes internal server error (500) to be seen via external proxy.

Discussion

On August 28th or 29th, I updated Discourse to the latest beta (v2.4.0.beta2) along with all the installed Discourse plug-ins. Around the same time, I also updated SeAT, and reconfigured Discourse to use a UNIX socket, which the external Apache can proxy/reverse proxy to. Prior to that, people were able to login via SeAT’s EvE Online SSO and new Discourse user accounts would be created for them if they didn’t already have one.

Since then, no new user accounts have successfully been created. Instead, the three people who have tried have generated Failed to create or lookup user: ERROR: duplicate key value violates constraint "idx_category_users_user_id_category_id" DETAIL: Key (user_id, category_id)=(36, 6) already exists. errors. The category_id is always 6 but the user_id varies between 33 and 44, even repeating numbers.

Assuming that category_id refers to entries in categories, then 6 seems to be Grass Clippings. Assuming that user_id refers to entries in users, then we don’t have any entries higher than 32.

Grass Clippings as a category is restricted for at least reading to people in the 2GTHRDiscourse, 2GTHRHighCouncil, and GRoLLake groups. At least one of the people trying to connect had an add_groups command that included all three groups. The first person did not yet have one of the three, and the middle person had at least one of the three. They all generate the same kind of database error with the identical details except except the user_id.

People with Discourse accounts created by logging in via SSO prior to the upgrades do not seem to be experiencing problems logging in.

Things Tried or Looked At

  1. Turning off force https and reverting back to external Apache proxying to nginx ports.
    Unsurprisingly, this had no effect.

  2. Debugging and fixing common SSO issues

  3. Watch out for double url encoding of SSO payload

  4. Followed through the backtrace and could see Discourse made it to models/discourse_single_sign_on.rb at line 203 of match_email_or_create_user() where it makes a call to User.create!(). Alas, the logging of the params, etc. is after that point, which it never gets to because it stops processing and returns a HTTP error 500. I checked shared/log/rails/production.log.* just in case.

Other Comments

  • SeAT: While the SeAT Discourse plug-in wasn’t updated, many components of SeAT were. It’s possible something in there has changed. However, the error is clearly on the Discourse side when trying to create or lookup a non-existent user, so I’m somewhat dubious the problem is on the SeAT side.

  • Discourse: I can’t remember what beta version of Discourse I was running before the upgrade. I’d guess it had probably been at least a month or two since I’d last upgraded.

Additional Details

Error
Failed to create or lookup user: ERROR:  duplicate key value violates unique constraint "idx_category_users_user_id_category_id"
DETAIL:  Key (user_id, category_id)=(36, 6) already exists.
.    add_groups: CORPBLUEP,2GTHRAllianceMember,2GTHRALL,2GTHRHighCouncil,2GTHRCorpDirector,2GTHROfficer,DoWCitadelGunner,HCDIM,CORPDIRBLUEP,2GTHRCorpRecruiter,CORPDIRLAWNS,CORPDIR123HC,GRoLLake,DoWCapital,DoWFax,User,CORPHRBLUEP,2GTHRDiscourse
admin: 
moderator: 
avatar_force_update: 
avatar_url: http://image.eveonline.com/Character/740426190_128.jpg
bio: 
card_background_url: 
email: something@somewhere.com
external_id: 740426190
groups: 
locale: 
locale_force_update: 
name: Mindframe
nonce: e6f9da9e62b720a1efd97348ca20f101
profile_background_url: 
remove_groups: Superuser,SPRKYAllianceMember,DoWFieldMarshall,DoWScoutCoordinator,DoWFCGang,DoWFCAlliance,DoWFCSenior,DoWScout,DoWSuper,DoWTitan,DoWFC,2GTHRCorpCEO,DoWTitanBridging,DoLLogisticsSov,DoLLogisticsShipping,HCDoW,HCDoL,HCDoC,HCDoF,DoCDoIT,DoCTechnoMage,DoCDiplomat,DoCDepartmentLead,DoCRecruiterPilots,DoCRecruiterCorporations,DoCDiplomatLead,DoWBLOP,ViewGroups,CORPAIEU,CORPDIRAIEU,CORPZBMC,CORPC.R.Y,CORP123HC,CORPALTBH,CORPLAWNS,CORPDIRZBMC,CORPDIRC.R.Y,CORPDIRALTBH,CORPF3R4L,CORPDIRF3R4L,CORPSPRKY,CORPDIRSPRKY,CORPRMKR,CORPDIRRMKR,CORPHR123HC,CORPHRAIEU,CORPHRZBMC,CORPHRC.R.Y,CORPHRF3R4L,SPRKYDiscourse,CORPHRLAWNS,CORPDIROUSYN,CORPHROUSYN,CORPOUSYN,DoWReimbursementTeam,DoWCarrier,DoWDread,WCMember,WCALL,WCMindframesMarketVisitors
require_activation: 
return_sso_url: 
suppress_welcome_message: 
title: 
username: Mindframe
website:     /var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-mini-profiler-1.0.2/lib/patches/db/pg.rb:110:in `async_exec'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-mini-profiler-1.0.2/lib/patches/db/pg.rb:110:in `async_exec'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/mini_sql-0.2.2/lib/mini_sql/postgres/connection.rb:118:in `run'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/mini_sql-0.2.2/lib/mini_sql/postgres/connection.rb:90:in `exec'
/var/www/discourse/app/models/user.rb:1403:in `set_default_categories_preferences'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:426:in `block in make_lambda'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:236:in `block in halting_and_conditional'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:517:in `block in invoke_after'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:517:in `each'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:517:in `invoke_after'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:133:in `run_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:816:in `_run_create_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/callbacks.rb:346:in `_create_record'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/timestamp.rb:102:in `_create_record'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/persistence.rb:705:in `create_or_update'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/callbacks.rb:342:in `block in create_or_update'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:132:in `run_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/callbacks.rb:342:in `create_or_update'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/persistence.rb:308:in `save!'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/validations.rb:52:in `save!'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/transactions.rb:315:in `block in save!'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `block in transaction'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
/usr/local/lib/ruby/2.6.0/monitor.rb:230:in `mon_synchronize'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `transaction'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/transactions.rb:212:in `transaction'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/transactions.rb:315:in `save!'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/suppressor.rb:48:in `save!'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/persistence.rb:53:in `create!'
/var/www/discourse/app/models/discourse_single_sign_on.rb:203:in `block in match_email_or_create_user'
/var/www/discourse/lib/distributed_mutex.rb:31:in `block in synchronize'
/var/www/discourse/lib/distributed_mutex.rb:27:in `synchronize'
/var/www/discourse/lib/distributed_mutex.rb:27:in `synchronize'
/var/www/discourse/lib/distributed_mutex.rb:12:in `synchronize'
/var/www/discourse/app/models/discourse_single_sign_on.rb:186:in `match_email_or_create_user'
/var/www/discourse/app/models/discourse_single_sign_on.rb:74:in `lookup_or_create_user'
/var/www/discourse/app/controllers/session_controller.rb:169:in `sso_login'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/abstract_controller/base.rb:194:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_controller/metal/rendering.rb:30:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:132:in `run_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:41:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_controller/metal/rescue.rb:22:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/notifications.rb:168:in `block in instrument'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/notifications.rb:168:in `instrument'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/abstract_controller/base.rb:134:in `process'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionview-5.2.3/lib/action_view/rendering.rb:32:in `process'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-mini-profiler-1.0.2/lib/mini_profiler/profiling_methods.rb:78:in `block in profile_method'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_controller/metal.rb:191:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_controller/metal.rb:252:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/journey/router.rb:35:in `each'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/journey/router.rb:35:in `serve'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/routing/route_set.rb:840:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-protection-2.0.7/lib/rack/protection/frame_options.rb:31:in `call'
/var/www/discourse/lib/middleware/omniauth_bypass_middleware.rb:68:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/tempfile_reaper.rb:15:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/conditional_get.rb:25:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/head.rb:12:in `call'
/var/www/discourse/lib/content_security_policy/middleware.rb:12:in `call'
/var/www/discourse/lib/middleware/anonymous_cache.rb:219:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:232:in `context'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:226:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:98:in `run_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/logster-2.3.2/lib/logster/middleware/reporter.rb:43:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/railties-5.2.3/lib/rails/rack/logger.rb:38:in `call_app'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/railties-5.2.3/lib/rails/rack/logger.rb:28:in `call'
/var/www/discourse/config/initializers/100-quiet_logger.rb:18:in `call'
/var/www/discourse/config/initializers/100-silence_logger.rb:31:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/var/www/discourse/lib/middleware/enforce_hostname.rb:17:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/method_override.rb:22:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/executor.rb:14:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/sendfile.rb:111:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-mini-profiler-1.0.2/lib/mini_profiler/profiler.rb:171:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/message_bus-2.2.2/lib/message_bus/rack/middleware.rb:57:in `call'
/var/www/discourse/lib/middleware/request_tracker.rb:169:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/railties-5.2.3/lib/rails/engine.rb:524:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/railties-5.2.3/lib/rails/railtie.rb:190:in `public_send'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/railties-5.2.3/lib/rails/railtie.rb:190:in `method_missing'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/urlmap.rb:68:in `block in call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/urlmap.rb:53:in `each'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/urlmap.rb:53:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/unicorn-5.5.1/lib/unicorn/http_server.rb:605:in `process_client'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/unicorn-5.5.1/lib/unicorn/http_server.rb:700:in `worker_loop'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/unicorn-5.5.1/lib/unicorn/http_server.rb:548:in `spawn_missing_workers'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/unicorn-5.5.1/lib/unicorn/http_server.rb:144:in `start'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/unicorn-5.5.1/bin/unicorn:128:in `<top (required)>'
/var/www/discourse/vendor/bundle/ruby/2.6.0/bin/unicorn:23:in `load'
/var/www/discourse/vendor/bundle/ruby/2.6.0/bin/unicorn:23:in `<main>'
3 Likes

This relates to this code:

What happened here is that we amended the index on category user like so:

Do you have a group that is both default watched and default tracked in site settings.

Look at: default categories watching default categories tracking default categories muted and default categories watching first post,

This fixes it:

diff --git a/app/models/user.rb b/app/models/user.rb
index c1a94949a6..85b2ca9244 100644
--- a/app/models/user.rb
+++ b/app/models/user.rb
@@ -1390,10 +1390,15 @@ class User < ActiveRecord::Base
     return if self.staged?
 
     values = []
+    # allocate set later
+    seen = nil
 
     %w{watching watching_first_post tracking muted}.each do |s|
       category_ids = SiteSetting.get("default_categories_#{s}").split("|").map(&:to_i)
       category_ids.each do |category_id|
+        seen ||= Set.new
+        next if seen.include?(category_id)
+        seen << category_id
         next if category_id == 0
         values << "(#{self.id}, #{category_id}, #{CategoryUser.notification_levels[s.to_sym]})"
       end
diff --git a/spec/models/user_spec.rb b/spec/models/user_spec.rb
index cc50d88b2e..4075ee6194 100644
--- a/spec/models/user_spec.rb
+++ b/spec/models/user_spec.rb
@@ -1603,8 +1603,12 @@ describe User do
 
       SiteSetting.default_categories_watching = category0.id.to_s
       SiteSetting.default_categories_tracking = category1.id.to_s
-      SiteSetting.default_categories_muted = category2.id.to_s
+
+      # this is invalid, but we don't validate so ensure nothing breaks
+      SiteSetting.default_categories_muted = "#{category2.id}|#{category0.id}"
+
       SiteSetting.default_categories_watching_first_post = category3.id.to_s
+
     end
 
     it "has overriden preferences" do

But I am not a fan of this fix, the site settings should validate that there is no overlap on save and we should migrate away the bad data.

@danielwaterworth I think you introduced the new constraint here, maybe followup with a validation when people set the site setting?

3 Likes

I have categories that are tracked and categories that are watched, but there’s no overlap between them. They’re all top-level categories. However, I have an overlap between default categories watching and default categories watching first post. A category is present in both of those and that category coincides with the category ID of the category mentioned in my DB constraint error. Could that be part of the problem?

Replying to myself: Removing the category from default categories watching first post so that it was only present in default categories watching solved the problem; someone without an account who previously could not log in can now do so.

2 Likes