RUBY-1743 Warn on handshake and auth failures (#1283)

Author: p-mongo

lib/mongo/server/connection.rb

@@ -217,59 +217,75 @@ def handshake!(socket)
           raise Error::HandshakeError, "Cannot handshake because there is no usable socket"
         end
 
+        response = average_rtt = nil
         @server.handle_handshake_failure! do
-          response, exc, rtt, average_rtt =
-            @server.monitor.round_trip_time_averager.measure do
-              socket.write(app_metadata.ismaster_bytes)
-              Protocol::Message.deserialize(socket, max_message_size).documents[0]
-            end
+          begin
+            response, exc, rtt, average_rtt =
+              @server.monitor.round_trip_time_averager.measure do
+                socket.write(app_metadata.ismaster_bytes)
+                Protocol::Message.deserialize(socket, max_message_size).documents[0]
+              end
 
-          if exc
-            raise exc
+            if exc
+              raise exc
+            end
+          rescue => e
+            log_warn("Failed to handshake with #{address}: #{e.class}: #{e}")
+            raise
           end
+        end
 
-          if response["ok"] == 1
-            # Auth mechanism is entirely dependent on the contents of
-            # ismaster response *for this connection*.
-            # Ismaster received by the monitoring connection should advertise
-            # the same wire protocol, but if it doesn't, we use whatever
-            # the monitoring connection advertised for filling out the
-            # server description and whatever the non-monitoring connection
-            # (that's this one) advertised for performing auth on that
-            # connection.
-            @auth_mechanism = if response['saslSupportedMechs']
-              if response['saslSupportedMechs'].include?(Mongo::Auth::SCRAM::SCRAM_SHA_256_MECHANISM)
-                :scram256
-              else
-                :scram
-              end
+        post_handshake(response, average_rtt)
+      end
+
+      # This is a separate method to keep the nesting level down.
+      def post_handshake(response, average_rtt)
+        if response["ok"] == 1
+          # Auth mechanism is entirely dependent on the contents of
+          # ismaster response *for this connection*.
+          # Ismaster received by the monitoring connection should advertise
+          # the same wire protocol, but if it doesn't, we use whatever
+          # the monitoring connection advertised for filling out the
+          # server description and whatever the non-monitoring connection
+          # (that's this one) advertised for performing auth on that
+          # connection.
+          @auth_mechanism = if response['saslSupportedMechs']
+            if response['saslSupportedMechs'].include?(Mongo::Auth::SCRAM::SCRAM_SHA_256_MECHANISM)
+              :scram256
             else
-              # MongoDB servers < 2.6 are no longer suported.
-              # Wire versions should always be returned in ismaster.
-              # See also https://jira.mongodb.org/browse/RUBY-1584.
-              min_wire_version = response[Description::MIN_WIRE_VERSION]
-              max_wire_version = response[Description::MAX_WIRE_VERSION]
-              features = Description::Features.new(min_wire_version..max_wire_version)
-              if features.scram_sha_1_enabled?
-                :scram
-              else
-                :mongodb_cr
-              end
+              :scram
             end
           else
-            @auth_mechanism = nil
+            # MongoDB servers < 2.6 are no longer suported.
+            # Wire versions should always be returned in ismaster.
+            # See also https://jira.mongodb.org/browse/RUBY-1584.
+            min_wire_version = response[Description::MIN_WIRE_VERSION]
+            max_wire_version = response[Description::MAX_WIRE_VERSION]
+            features = Description::Features.new(min_wire_version..max_wire_version)
+            if features.scram_sha_1_enabled?
+              :scram
+            else
+              :mongodb_cr
+            end
           end
-
-          new_description = Description.new(address, response, average_rtt)
-          @server.monitor.publish(Event::DESCRIPTION_CHANGED, @server.description, new_description)
+        else
+          @auth_mechanism = nil
         end
+
+        new_description = Description.new(address, response, average_rtt)
+        @server.monitor.publish(Event::DESCRIPTION_CHANGED, @server.description, new_description)
       end
 
       def authenticate!(pending_connection)
         if options[:user] || options[:auth_mech]
           user = Auth::User.new(Options::Redacted.new(:auth_mech => default_mechanism).merge(options))
           @server.handle_auth_failure! do
-            Auth.get(user).login(pending_connection)
+            begin
+              Auth.get(user).login(pending_connection)
+            rescue => e
+              log_warn("Failed to handshake with #{address}: #{e.class}: #{e}")
+              raise
+            end
           end
         end
       end

lib/mongo/server/monitor/connection.rb

@@ -227,6 +227,9 @@ def handshake!(socket)
             set_compressor!(reply)
             reply
           end
+        rescue => e
+          log_warn("Failed to handshake with #{address}: #{e.class}: #{e}")
+          raise
         end
 
         def retry_message

spec/mongo/server/connection_spec.rb

@@ -8,11 +8,7 @@ class ConnectionSpecTestException < Exception; end
     ClientRegistry.instance.close_all_clients
   end
 
-  after(:all) do
-    ClientRegistry.instance.close_all_clients
-  end
-
-  let(:address) do
+  let!(:address) do
     default_address
   end
 
@@ -43,10 +39,9 @@ class ConnectionSpecTestException < Exception; end
 
   declare_topology_double
 
+  let(:server_options) { SpecConfig.instance.test_options.merge(monitoring_io: false) }
   let(:server) do
-    Mongo::Server.new(address, cluster, monitoring, listeners,
-      SpecConfig.instance.test_options.merge(monitoring_io: false),
-    )
+    Mongo::Server.new(address, cluster, monitoring, listeners, server_options)
   end
 
   let(:monitored_server) do
@@ -142,6 +137,23 @@ class ConnectionSpecTestException < Exception; end
         end
       end
 
+      shared_examples_for 'logs a warning' do
+        let(:expected_message) do
+          "MONGODB | Failed to handshake with #{address}: #{error.class}: #{error}"
+        end
+
+        it 'logs a warning' do
+          messages = []
+          # Straightforward expectations are not working here for some reason
+          expect(Mongo::Logger.logger).to receive(:warn) do |msg|
+            messages << msg
+          end
+          expect(error).not_to be nil
+          expect(messages).to include(expected_message)
+        end
+
+      end
+
       context 'when #handshake! dependency raises a non-network exception' do
 
         let(:exception) do
@@ -181,15 +193,24 @@ class ConnectionSpecTestException < Exception; end
 
         it_behaves_like 'failing connection'
         it_behaves_like 'marks server unknown'
+        it_behaves_like 'logs a warning'
       end
 
       context 'when #authenticate! raises an exception' do
+        require_auth
+
+        let(:server_options) do
+          SpecConfig.instance.test_options.merge(monitoring_io: false).
+            merge(SpecConfig.instance.auth_options)
+        end
+
         let(:exception) do
           Mongo::Error::OperationFailure.new
         end
 
         let(:error) do
-          expect(connection).to receive(:authenticate!).and_raise(exception)
+          expect(Mongo::Auth).to receive(:get).and_raise(exception)
+          expect(connection.send(:socket)).to be nil
           begin
             connection.connect!
           rescue Exception => e
@@ -200,6 +221,7 @@ class ConnectionSpecTestException < Exception; end
         end
 
         it_behaves_like 'failing connection'
+        it_behaves_like 'logs a warning'
       end
 
       context 'when a non-Mongo exception is raised' do

spec/mongo/server/monitor/connection_spec.rb

@@ -158,4 +158,26 @@
       end
     end
   end
+
+  describe '#connect!' do
+    context 'network error' do
+      before do
+        address
+        server.monitor.instance_variable_get('@thread').kill
+        server.monitor.connection.disconnect!
+        expect_any_instance_of(Mongo::Socket).to receive(:write).and_raise(Mongo::Error::SocketError, 'test error')
+      end
+
+      let(:options) { SpecConfig.instance.test_options }
+
+      let(:expected_message) { "MONGODB | Failed to handshake with #{address}: Mongo::Error::SocketError: test error" }
+
+      it 'logs a warning' do
+        expect(Mongo::Logger.logger).to receive(:warn).with(expected_message).and_call_original
+        expect do
+          server.monitor.connection.connect!
+        end.to raise_error(Mongo::Error::SocketError, 'test error')
+      end
+    end
+  end
 end

spec/support/constraints.rb

@@ -138,15 +138,15 @@ def ruby_version_lt(version)
 
   def require_auth
     before do
-      unless ENV['AUTH'] == 'auth' || ClusterConfig.instance.auth_enabled?
+      unless ENV['AUTH'] == 'auth' || SpecConfig.instance.user || ClusterConfig.instance.auth_enabled?
         skip "Auth required"
       end
     end
   end
 
   def require_no_auth
     before do
-      if ENV['AUTH'] == 'auth' || ClusterConfig.instance.auth_enabled?
+      if ENV['AUTH'] == 'auth' || SpecConfig.instance.user || ClusterConfig.instance.auth_enabled?
         skip "Auth not allowed"
       end
     end

spec/support/spec_config.rb

@@ -148,6 +148,14 @@ def test_db
 
   # Option hashes
 
+  def auth_options
+    {
+      user: user,
+      password: password,
+      auth_source: auth_source,
+    }
+  end
+
   def ssl_options
     if ssl?
       {