Discussion forum errors in latest master with mongo 3.2

Site Operators
1

We’re seeing access errors when running the latest master version of the discussion forum code. These problems don’t arise when using the current open-release/juniper.alpha1 branch, but I’ve tagged this as a Juniper issue because I’m concerned that it will break when the next juniper candidate branch is made from master.

We’re running mongo 3.2.19, and plan to upgrade to 3.6.x, but have not yet done so.

The cs_comments_service code comparison between master and juniper.alpha1 shows several attempts and reverts at upgrading the ruby driver, so perhaps there’s been an incompatibility with mongo 3.2 introduced? Or some configuration change we need to make to accommodate? @billatedx do you have any suggestions here?

The modulestore/contentstore are still working as expected, but inline discussion blocks throw errors, cf sandbox Demo course, Working with Videos.

Traceback from /edx/var/log/supervisor/forum-stderr.log

The tobuasnhzmyzflbk exists and has the correct privileges on the configpr5723_sandbox_opencraft_hosting_forum database.

==> /edx/var/log/supervisor/forum-stderr.log <==
2020-04-14 01:32:26 - Mongo::Auth::Unauthorized - User tobuasnhzmyzflbk is not authorized to access configpr5723_sandbox_opencraft_hosting_forum.:
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/auth/scram/conversation.rb:489:in `validate!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/auth/scram/conversation.rb:477:in `validate_final_message!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/auth/scram/conversation.rb:151:in `finalize'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/auth/scram.rb:63:in `login'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server/connection.rb:249:in `block in authenticate!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server.rb:267:in `handle_auth_failure!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server/connection.rb:248:in `authenticate!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server/connection.rb:100:in `connect!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server/connectable.rb:84:in `ensure_connected'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server/connection.rb:270:in `write'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server/connection.rb:229:in `deliver'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server/connection.rb:144:in `block in dispatch'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/monitoring/publishable.rb:47:in `publish_command'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server/connection.rb:143:in `dispatch'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/operation/shared/executable.rb:33:in `block in dispatch_message'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server/connection_pool.rb:110:in `with_connection'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/server.rb:251:in `with_connection'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/operation/shared/executable.rb:32:in `dispatch_message'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/operation/find/command.rb:41:in `execute'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/operation/find.rb:45:in `execute'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/collection/view/iterable.rb:82:in `send_initial_query'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongoid-7.0.5/lib/mongoid/query_cache.rb:232:in `block in each'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongo-2.5.3/lib/mongo/retryable.rb:44:in `read_with_retry'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongoid-7.0.5/lib/mongoid/query_cache.rb:230:in `each'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongoid-7.0.5/lib/mongoid/contextual/mongo.rb:279:in `first'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongoid-7.0.5/lib/mongoid/contextual/mongo.rb:279:in `find_first'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongoid-7.0.5/lib/mongoid/contextual.rb:20:in `find_first'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongoid-7.0.5/lib/mongoid/findable.rb:114:in `find_by'
	/edx/app/forum/cs_comments_service/lib/helpers.rb:13:in `user'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/method_tracer.rb:329:in `block in user_with_trace_Custom_Sinatra_Application_user'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/method_tracer_helpers.rb:30:in `trace_execution_scoped'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/method_tracer.rb:327:in `user_with_trace_Custom_Sinatra_Application_user'
	/edx/app/forum/cs_comments_service/api/users.rb:16:in `block in <top (required)>'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1610:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1610:in `block in compile!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `block (3 levels) in route!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:994:in `route_eval'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/sinatra.rb:138:in `route_eval_with_newrelic'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `block (2 levels) in route!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1015:in `block in process_route'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1013:in `catch'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1013:in `process_route'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/sinatra.rb:118:in `process_route_with_newrelic'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:973:in `block in route!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:972:in `each'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:972:in `route!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1085:in `block in dispatch!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `block in invoke'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `catch'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `invoke'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1082:in `dispatch!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/sinatra.rb:163:in `dispatch_and_notice_errors_with_newrelic'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/sinatra.rb:149:in `block in dispatch_with_newrelic'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:370:in `perform_action_with_newrelic_trace'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/sinatra.rb:146:in `dispatch_with_newrelic'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:907:in `block in call!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `block in invoke'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `catch'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `invoke'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:907:in `call!'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:895:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/rack/agent_hooks.rb:30:in `traced_call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/rack/browser_monitoring.rb:32:in `traced_call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/bundler/gems/rack-contrib-6ff3ca2b2d98/lib/rack/contrib/locale.rb:15:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-1.6.8/lib/rack/logger.rb:15:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-1.6.8/lib/rack/commonlogger.rb:33:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:219:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:212:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-1.6.8/lib/rack/head.rb:13:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-1.6.8/lib/rack/methodoverride.rb:22:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:182:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:2013:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1487:in `block in call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1787:in `synchronize'
	/edx/app/forum/.gem/ruby/2.5.0/gems/sinatra-1.4.8/lib/sinatra/base.rb:1487:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongoid-7.0.5/lib/mongoid/query_cache.rb:118:in `block in call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongoid-7.0.5/lib/mongoid/query_cache.rb:69:in `cache'
	/edx/app/forum/.gem/ruby/2.5.0/gems/mongoid-7.0.5/lib/mongoid/query_cache.rb:118:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-timeout-0.4.2/lib/rack/timeout/core.rb:122:in `block in call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-timeout-0.4.2/lib/rack/timeout/support/timeout.rb:19:in `timeout'
	/edx/app/forum/.gem/ruby/2.5.0/gems/rack-timeout-0.4.2/lib/rack/timeout/core.rb:121:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/newrelic_rpm-5.6.0.349/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
	/edx/app/forum/.gem/ruby/2.5.0/gems/unicorn-5.3.1/lib/unicorn/http_server.rb:606:in `process_client'
	/edx/app/forum/.gem/ruby/2.5.0/gems/unicorn-5.3.1/lib/unicorn/http_server.rb:702:in `worker_loop'
	/edx/app/forum/.gem/ruby/2.5.0/gems/unicorn-5.3.1/lib/unicorn/http_server.rb:549:in `spawn_missing_workers'
	/edx/app/forum/.gem/ruby/2.5.0/gems/unicorn-5.3.1/lib/unicorn/http_server.rb:142:in `start'
	/edx/app/forum/.gem/ruby/2.5.0/gems/unicorn-5.3.1/bin/unicorn:126:in `<top (required)>'
	/edx/app/forum/cs_comments_service/bin/unicorn:16:in `load'
	/edx/app/forum/cs_comments_service/bin/unicorn:16:in `<main>'
I, [2020-04-14T01:32:26.384504 #29669]  INFO -- : source=rack-timeout id=09e62037e45a5e3489778b3ae35b2316 timeout=20000ms service=93ms state=completed
2

Should this be a Jira ticket in the Juniper epic?

3

Thanks @nedbat, I’ve created CRI-186.

4

@jill the upgrades were tested against 3.2, 3.4, and 3.6 on our staging server and we did not run into this this error, however that doesn’t mean it’s necessarily unrelated, just a data point.

5

Thanks for the info @billatedx ! I think I found the problem, but would appreciate your input on how best to address it. CC @nedbat

TL;DR Would you accept forum+configuration PRs that make the :auth_mech configurable?

This bug report RUBY-1684 led me to try manually patching config/mongoid.yml, which fixed the issue for us:

diff --git a/config/mongoid.yml b/config/mongoid.yml
index 1997873..eaeb581 100644
--- a/config/mongoid.yml
+++ b/config/mongoid.yml
@@ -9,6 +9,7 @@ common: &default_client
     timeout: <%= ENV['MONGOID_TIMEOUT'] || 0.5 %>
     ssl: <%= ENV['MONGOID_USE_SSL'] || false %>
     auth_source: <%= ENV['MONGOID_AUTH_SOURCE'] || '' %>
+    auth_mech: :mongodb_cr
 
 common_uri: &default_uri
   uri: <%= ENV['MONGOHQ_URL'] %>

The ruby 2.5 driver docs say:

:auth_mech: Specifies the authentication mechanism to use. Can be one of: :mongodb_cr , :mongodb_x509 , :plain , :scram . Symbol.
MongoDB 3.0 and later: :scram if user credentials are supplied but an :auth_mech is not.
2.6 and earlier: :mongodb_cr

Our connection string does include user credentials:

export MONGOHQ_URL="mongodb://<user>:<pass>@mongodb-secondary-2.net.opencraft.hosting:27017,mongodb.opencraft.hosting:27017,mongodb-secondary-1.net.opencraft.hosting:27017/<dbname>?replicaSet=rs0"

But we haven’t upgraded our authentication mechanism to SCRAM yet. Support for mongodb_cr is dropped in mongo 4.0, so we will need to do this at some point, but we’d much prefer to do it after upgrading our clients to Juniper, so that it’s supported by the drivers.

1 Like
6

Seems like a pretty straight forward PR. Let me know when you have something for me to review and we can get it in :+1:

1 Like
7

Issue resolved by these PRs:

Anyone experiencing these issues will either need to update their Mongo authentication mechanism to SCRAM (which will be required in mongo 4.0), or use this ansible variable to use the older authentication mechanism instead:

FORUM_MONGO_AUTH_MECH: ":mongodb_cr"

Thank you so much for your help with these PRs @billatedx!

8

If the PRs fixed the issue, then who will be experiencing issues? Or did you mean, “if you are running older code and experiencing these issue”?

9

These PRs make it possible to specify which mongo authentication mechanism you’re using. The default uses the new Salted Challenge Response Authentication Mechanism (SCRAM). But you can specify the older challenge-response :mongodb_cr mechanism if you haven’t converted to SCRAM yet.