SSO new user creation not working


(Sunny) #1

Hey everyone,

We have an issue that appeared today and could use some help. We are using Discourse and syncing with our main site using SSO.

Existing users are able to log in just fine and use both sites normally. However, new users cannot register new accounts. Our development team is saying the error message is from Discourse is:

“Server error: POST https://discussions.ftw.in/users.json resulted in a 500 Internal Server Error response”

Its worthwhile to note we are in the process of migrating both sites to Digital Ocean and right now and our Discourse site is still on AWS. We have not pushed new code or changed any settings today. We are also on the latest version of Discourse.

Any help would be greatly appreciated.

Thanks


(Jeff Atwood) #2

Did you check /logs on the Discourse side in your web browser? You can also enable verbose sso in your site settings.


(Sunny) #3

Hey Jeff,

Thanks for helping out.

Yes, Verbose logging is on.

I tailed the production log and tried to create a new user and this was in the log:

`Started POST "/users.json" for 138.197.2.149 at 2017-10-26 01:46:01 +0000
Processing by UsersController#create as JSON
  Parameters: {"api_key"=>"[FILTERED]", "api_username"=>"administrator", "name"=>"", "username"=>"codinghorrortest", "email"=>"sunn.y@beerock.com", "password"=>"[FILTERED]", "active"=>"1"}
  Rendering text template
  Rendered text template (0.0ms)
Completed 500 Internal Server Error in 73ms (Views: 0.9ms | ActiveRecord: 53.3ms)`

Let me know if that give you more insight and if you need more info.


(Jeff Atwood) #4

I said to look at /logs in your web browser when logged in as admin. Did you try that?


(Sunny) #5

Yes, I’ve looked at the log page. I see a lot of warnings about “Started SSO process nonce”, “User was logged on” and “Nonce has already expired” notice.

Nothing comes up with the filter for Fatal or Error. I even have monitored the log page while creating new users but nothing seems to be logged about that action.


(Sunny) #6

checking again this morning, now I do see some Errors:

Message (22 copies reported)
Job exception: end of file reached
Backtrace

Env

hostname	ftw-app
process_id	158
application_version	f30366744a3136bd7134dd2fc86897829f2b3d5d
current_db	default
current_hostname	discussions.ftw.in
job	Jobs::UserEmail
problem_db	default
opts	
type	digest
user_id	[4968, 4991, 5028, 5004, 5016, 5032, 5038, 5057, 5039, 24095, 24250, 25615, 25620, 25637, 25672, 25647, 6284, 6329, 6375, 6396, 6409, 6428]
current_site_id	default

and

Message
Job exception: Net::ReadTimeout
Backtrace

/usr/local/lib/ruby/2.4.0/net/protocol.rb:176:in `rbuf_fill'
/usr/local/lib/ruby/2.4.0/net/protocol.rb:154:in `readuntil'
/usr/local/lib/ruby/2.4.0/net/protocol.rb:164:in `readline'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:950:in `recv_response'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:912:in `block in data'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:960:in `critical'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:898:in `data'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:659:in `block in send_message'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:854:in `rcptto_list'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:659:in `send_message'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mail-2.6.6/lib/mail/network/delivery_methods/smtp.rb:112:in `block in deliver!'
/usr/local/lib/ruby/2.4.0/net/smtp.rb:519:in `start'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mail-2.6.6/lib/mail/network/delivery_methods/smtp.rb:111:in `deliver!'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mail-2.6.6/lib/mail/message.rb:2149:in `do_delivery'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mail-2.6.6/lib/mail/message.rb:237:in `block in deliver'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/actionmailer-5.1.4/lib/action_mailer/base.rb:558:in `block in deliver_mail'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications.rb:166:in `block in instrument'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications.rb:166:in `instrument'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/actionmailer-5.1.4/lib/action_mailer/base.rb:556:in `deliver_mail'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mail-2.6.6/lib/mail/message.rb:237:in `deliver'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/actionmailer-5.1.4/lib/action_mailer/message_delivery.rb:96:in `block in deliver_now'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/actionmailer-5.1.4/lib/action_mailer/rescuable.rb:15:in `handle_exceptions'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/actionmailer-5.1.4/lib/action_mailer/message_delivery.rb:95:in `deliver_now'
/var/www/discourse/lib/email/sender.rb:184:in `send'
/var/www/discourse/app/jobs/regular/user_email.rb:41:in `execute'
/var/www/discourse/app/jobs/base.rb:134:in `block (2 levels) in perform'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/rails_multisite-1.1.0.rc4/lib/rails_multisite/connection_management.rb:71:in `with_connection'
/var/www/discourse/app/jobs/base.rb:129:in `block in perform'
/var/www/discourse/app/jobs/base.rb:125:in `each'
/var/www/discourse/app/jobs/base.rb:125:in `perform'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:188:in `execute_job'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:170:in `block (2 levels) in process'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
/var/www/discourse/lib/sidekiq/pausable.rb:80:in `call'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:169:in `block in process'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:141:in `block (6 levels) in dispatch'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/job_retry.rb:97:in `local'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:140:in `block (5 levels) in dispatch'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq.rb:36:in `block in <module:Sidekiq>'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:136:in `block (4 levels) in dispatch'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:204:in `stats'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:131:in `block (3 levels) in dispatch'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/job_logger.rb:7:in `call'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:130:in `block (2 levels) in dispatch'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/job_retry.rb:72:in `global'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:129:in `block in dispatch'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/logging.rb:44:in `with_context'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/logging.rb:38:in `with_job_hash_context'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:128:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:168:in `process'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:85:in `process_one'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/processor.rb:73:in `run'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/util.rb:16:in `watchdog'
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.0.5/lib/sidekiq/util.rb:25:in `block in safe_thread'
Env

hostname	ftw-app
process_id	158
application_version	f30366744a3136bd7134dd2fc86897829f2b3d5d
current_db	default
current_hostname	discussions.ftw.in
job	Jobs::UserEmail
problem_db	default
opts	
type	digest
user_id	4957
current_site_id	default

(Jeff Atwood) #7

That looks like a networking problem of some kind.


(Jay Pfaffman) #8

No. It’s worse than that.

Somehow the SSO code is redirecting the wrong place. Here’s the error that gets printed if you try to create an account:

ServerException in RequestException.php line 113:
Server error: `POST https://HOSTNAME/users.json` resulted in a `500 Internal Server Error` response
in RequestException.php line 113
at RequestException::create(object(Request), object(Response)) in Middleware.php line 65
at Middleware::GuzzleHttp\{closure}(object(Response)) in Promise.php line 203
at Promise::callHandler('1', object(Response), array(object(Promise), object(Closure), null)) in Promise.php line 156
at Promise::GuzzleHttp\Promise\{closure}() in TaskQueue.php line 47
at TaskQueue->run(true) in Promise.php line 246
at Promise->invokeWaitFn() in Promise.php line 223
at Promise->waitIfPending() in Promise.php line 267
at Promise->invokeWaitList() in Promise.php line 225
at Promise->waitIfPending() in Promise.php line 62
at Promise->wait() in Client.php line 131
at Client->request('POST', 'users.json', array('form_params' => array('api_key' => 'THEWHOLE_REAL_API_KEY_FOR_ALL_THE_WORLD_TO_SEE', 'api_username' => 'administrator', 'name' => 'Jay Pfaffman', 'username' => 'pfaffman', 'email' => 'pfaffman@relaxpc.com', 'password' => '1f86w8du1509048506', 'active' => true), 'synchronous' => true)) in DiscourseController.php line 199
at DiscourseController->doDiscourseRegister(array('name' => 'Jay Pfaffman', 'username' => 'pfaffman', 'email' => 'pfaffman@relaxpc.com', 'password' => '150904850659f240ba7f8fd1509048506')) in SocialAuthController.php line 248
at SocialAuthController->completeAccount(object(Request))
at call_user_func_array(array(object(SocialAuthController), 'completeAccount'), array(object(Request))) in Controller.php line 55
at Controller->callAction('completeAccount', array(object(Request))) in ControllerDispatcher.php line 44
at ControllerDispatcher->dispatch(object(Route), object(SocialAuthController), 'completeAccount') in Route.php line 189


(Jay Pfaffman) #9

Well, no. That does appear to be the correct API call to create a user.

Doing that with curl returns

{"success":true,"active":false,"message":"\u003cp\u003eYou’re almost done! We sent an activation mail to \u003cb\u003epfaffman@gmail.com\u003c/b\u003e. Please follow the instructions in the mail to activate your account.\u003c/p\u003e\u003cp\u003eIf it doesn’t arrive, check your spam folder.\u003c/p\u003e"}pfaffman@balloon:~$ curl --verbose -H "Content-Type: application/json" -d '{"apb296a7173b6781a2793765EXTRA", "api_username":"administrator", "name":"Jay Pfaffman", "username":"jaypfaffman", "email":"pfaffman@gmail.com", "password":"vb13bh9a1509056880", "active":true, "approved":true}' 

But the email is never delivered and requests for that user ID suggest that the user is not created.

And it gives the same response even with a bogus API key, but I know that I have a legit api key because I can use it to retrieve system settings.

And on my site I can do

curl --verbose -H "Content-Type: application/json" -d '{"api_key":"NOTANAPIKEY", "api_username":"administrator", "name":"Jay Pfaffman", "username":"jaypfaffman", "email":"pfaffman@gmail.com", "password":"vb13bh9a1509056880", "active":true}'  https://discussions.ftw.in/users.json

and get the same response that I do if I use the real API key.

* upload completely sent off: 184 out of 184 bytes
< HTTP/1.1 200 OK
< Date: Thu, 26 Oct 2017 23:13:01 GMT
< Content-Type: application/json; charset=utf-8
< Transfer-Encoding: chunked
< Connection: keep-alive
< Set-Cookie: __cfduid=d78ae2e7ab930136df43175c93f64a6451509059580; expires=Fri, 26-Oct-18 23:13:00 GMT; path=/; domain=.ftw.in; HttpOnly; Secure
< Vary: Accept-Encoding
< X-Frame-Options: SAMEORIGIN
< X-XSS-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Discourse-Route: users/create
< X-Request-Id: d0bdb0df-4448-4213-9830-109c468124a5
< X-Runtime: 0.007744
< Referrer-Policy: no-referrer-when-downgrade
< Strict-Transport-Security: max-age=31536000
< Server: cloudflare-nginx
< CF-RAY: 3b411a8cecac776c-LAX
< 
* Connection #0 to host discussions.ftw.in left intact
{"success":true,"active":false,
"message":"\u003cp\u003eYou’re almost done! We sent an activation mail to \u003cb\u003epfaffman@gmail.com\u003c/b\u003e. Please follow the instructions in the mail to activate your account.\u003c/p\u003e\u003cp\u003eIf it doesn’t arrive, check your spam folder.\u003c/p\u003e"}

That seems like a :bug:

But when I look at the logs on my site I get this in logs:

Logs say this, though: "Filter chain halted as :respond_to_suspicious_request rendered or redirected

I don’t see now to debug creating a user via API if Discourse reports 200 and silently fails.