RUBY-2525 Expose the Reason an Operation Fails Document Validation (#2379)

* RUBY-2525 add details to operation failure

* RUBY-2525 add details to message and tests

* RUBY-2525 update comments

* RUBY-2525 remove unnecessary assignment

* RUBY-2525 clean up retrieve details

* RUBY-2525 augment bulk write error message and test

* RUBY-2525 add check in bulkwriteerror test

* RUBY-2525 fix tests for before WriteError server imp

* RUBY-2525 fix broken test

* RUBY-2525 fix regex in test

* RUBY-2525 change condition

* RUBY-2525 add comments, cleanup conditions

* RUBY-2525 add bulk_write message comment

* RUBY-2525 fix bulk write message comment

* RUBY-2525 fix test rescue

Author: neilshweky

lib/mongo/error/bulk_write_error.rb

@@ -55,15 +55,42 @@ def initialize(result)
 
       private
 
+      # Generates an error message when there are multiple write errors.
+      #
+      # @example Multiple documents fail validation
+      #
+      # col has validation { 'validator' => { 'x' => { '$type' => 'string' } } }
+      # col.insert_many([{_id: 1}, {_id: 2}], ordered: false)
+      #
+      # Multiple errors:
+      #   [121]: Document failed validation --
+      #     {"failingDocumentId":1,"details":{"operatorName":"$type",
+      #     "specifiedAs":{"x":{"$type":"string"}},"reason":"field was
+      #     missing"}};
+      #   [121]: Document failed validation --
+      #     {"failingDocumentId":2, "details":{"operatorName":"$type",
+      #     "specifiedAs":{"x":{"$type":"string"}}, "reason":"field was
+      #     missing"}}
+      #
+      # @return [ String ] The error message
       def build_message
         errors = @result['writeErrors']
         return nil unless errors
 
-        fragment = errors.first(10).map do |error|
-          "[#{error['code']}]: #{error['errmsg']}"
-        end.join('; ')
+        fragment = ""
+        cut_short = false
+        errors.first(10).each_with_index do |error, i|
+          fragment += "; " if fragment.length > 0
+          fragment += "[#{error['code']}]: #{error['errmsg']}"
+          fragment += " -- #{error['errInfo'].to_json}" if error['errInfo']
+
+          if fragment.length > 3000
+            cut_short = i < [9, errors.length].min
+            break
+          end
+        end
 
-        fragment += '...' if errors.length > 10
+        fragment += '...' if errors.length > 10 || cut_short
 
         if errors.length > 1
           fragment = "Multiple errors: #{fragment}"

lib/mongo/error/operation_failure.rb

@@ -224,6 +224,12 @@ def write_concern_error?
       # @since 2.10.0
       attr_reader :write_concern_error_code_name
 
+      # @return [ String | nil ] The details of the error.
+      #   For WriteConcernErrors this is `document['writeConcernError']['errInfo']`.
+      #   For WriteErrors this is `document['writeErrors'][0]['errInfo']`.
+      #   For all other errors this is nil.
+      attr_reader :details
+
       # @return [ BSON::Document | nil ] The server-returned error document.
       #
       # @api experimental
@@ -258,10 +264,10 @@ def write_concern_error?
       # @option options [ Array<String> ] :labels The set of labels associated
       #   with the error.
       # @option options [ true | false ] :wtimeout Whether the error is a wtimeout.
-      #
-      # @since 2.5.0, options added in 2.6.0
       def initialize(message = nil, result = nil, options = {})
-        super(message)
+        @details = retrieve_details(options[:document])
+        super(append_details(message, @details))
+
         @result = result
         @code = options[:code]
         @code_name = options[:code_name]
@@ -306,6 +312,28 @@ def unsupported_retryable_write?
         # either having string keys or providing indifferent access.
         code == 20 && server_message&.start_with?("Transaction numbers") || false
       end
+
+      private
+
+      # Retrieve the details from a document
+      #
+      # @return [ Hash | nil ] the details extracted from the document
+      def retrieve_details(document)
+        return nil unless document
+        if wce = document['writeConcernError']
+          return wce['errInfo']
+        elsif we = document['writeErrors']&.first
+          return we['errInfo']
+        end
+      end
+
+      # Append the details to the message
+      #
+      # @return [ String ] the message with the details appended to it
+      def append_details(message, details)
+        return message unless details && message
+        message + " -- #{details.to_json}"
+      end
     end
   end
 end

spec/integration/bulk_write_error_message_spec.rb

@@ -38,4 +38,36 @@
       end
     end
   end
+
+  context 'a bulk write with validation errors' do
+
+    let(:collection_name) { 'bulk_write_error_validation_message_spec' }
+
+    let(:collection) do
+      client[:collection_name].drop
+      client[:collection_name,
+      {
+        'validator' => {
+          'x' => { '$type' => 'string' },
+        }
+      }].create
+      client[:collection_name]
+    end
+
+    it 'reports code name, code, message, and details' do
+      begin
+        collection.insert_one({_id:1, x:"1"})
+        collection.insert_many([
+          {_id: 1, x:"1"},
+          {_id: 2, x:1},
+        ], ordered: false)
+        fail('Should have raised')
+      rescue Mongo::Error::BulkWriteError => e
+        e.message.should =~ %r,\AMultiple errors: \[11000\]: (insertDocument :: caused by :: 11000 )?E11000 duplicate key error (collection|index):.*\; \[121\]: Document failed validation( -- .*)?,
+        # The duplicate key error should not print details because it's not a
+        # WriteError or a WriteConcernError
+        e.message.scan(/ -- /).length.should be <= 1
+      end
+    end
+  end
 end

spec/mongo/error/operation_failure_heavy_spec.rb

@@ -40,6 +40,9 @@
       begin
         authorized_client['foo'].insert_one(test: 1)
       rescue Mongo::Error::OperationFailure => exc
+        expect(exc.details).to eq(exc.document['writeConcernError']['errInfo'])
+        expect(exc.server_message).to eq(exc.document['writeConcernError']['errmsg'])
+        expect(exc.code).to eq(exc.document['writeConcernError']['code'])
       else
         fail 'Expected an OperationFailure'
       end
@@ -58,4 +61,50 @@
       }
     end
   end
+
+  describe 'WriteError details' do
+    min_server_fcv '5.0'
+
+    let(:subscriber) { Mrss::EventSubscriber.new }
+
+    let(:subscribed_client) do
+      authorized_client.tap do |client|
+        client.subscribe(Mongo::Monitoring::COMMAND, subscriber)
+      end
+    end
+
+    let(:collection_name) { 'write_error_prose_spec' }
+
+    let(:collection) do
+      subscribed_client[:collection_name].drop
+      subscribed_client[:collection_name,
+      {
+        'validator' => {
+          'x' => { '$type' => 'string' },
+        }
+      }].create
+      subscribed_client[:collection_name]
+    end
+
+    context 'when there is a write error' do
+      it 'succeeds and prints the error' do
+        begin
+          collection.insert_one({x: 1})
+        rescue Mongo::Error::OperationFailure => e
+          insert_events = subscriber.succeeded_events.select { |e| e.command_name == "insert" }
+          expect(insert_events.length).to eq 1
+          expect(e.message).to match(/\[#{e.code}(:.*)?\].+ -- .+/)
+
+          expect(e.details).to eq(e.document['writeErrors'][0]['errInfo'])
+          expect(e.server_message).to eq(e.document['writeErrors'][0]['errmsg'])
+          expect(e.code).to eq(e.document['writeErrors'][0]['code'])
+
+          expect(e.code).to eq 121
+          expect(e.details).to eq(insert_events[0].reply['writeErrors'][0]['errInfo'])
+        else
+          fail 'Expected an OperationFailure'
+        end
+      end
+    end
+  end
 end