Merge pull request #402 from newellista/add-error-reason-to-logs

Add error reason to logs

Author: film42

lib/protobuf/rpc/connectors/base.rb

@@ -63,8 +63,9 @@ def data_callback(data)
         # @param [String] message The error message
         def failure(code, message)
           @error = ClientError.new
-          @error.code = ::Protobuf::Socketrpc::ErrorReason.fetch(code)
+          @stats.status = @error.code = ::Protobuf::Socketrpc::ErrorReason.fetch(code)
           @error.message = message
+
           logger.debug { sign_message("Server failed request (invoking on_failure): #{@error.inspect}") }
 
           @failure_cb.call(@error) unless @failure_cb.nil?

lib/protobuf/rpc/stat.rb

@@ -1,16 +1,30 @@
 require 'date'
 require 'time'
 require 'protobuf/logging'
+require 'protobuf/rpc/rpc.pb'
 
 module Protobuf
   module Rpc
     class Stat
       attr_accessor :mode, :start_time, :end_time, :request_size, :dispatcher
-      attr_accessor :response_size, :client, :service, :method_name
+      attr_accessor :response_size, :client, :service, :method_name, :status
       attr_reader   :server
 
       MODES = [:SERVER, :CLIENT].freeze
 
+      ERROR_TRANSLATIONS = {
+        ::Protobuf::Socketrpc::ErrorReason::BAD_REQUEST_DATA => "BAD_REQUEST_DATA",
+        ::Protobuf::Socketrpc::ErrorReason::BAD_REQUEST_PROTO => "BAD_REQUEST_PROTO",
+        ::Protobuf::Socketrpc::ErrorReason::SERVICE_NOT_FOUND => "SERVICE_NOT_FOUND",
+        ::Protobuf::Socketrpc::ErrorReason::METHOD_NOT_FOUND => "METHOD_NOT_FOUND",
+        ::Protobuf::Socketrpc::ErrorReason::RPC_ERROR => "RPC_ERROR",
+        ::Protobuf::Socketrpc::ErrorReason::RPC_FAILED => "RPC_FAILED",
+        ::Protobuf::Socketrpc::ErrorReason::INVALID_REQUEST_PROTO => "INVALID_REQUEST_PROTO",
+        ::Protobuf::Socketrpc::ErrorReason::BAD_RESPONSE_PROTO => "BAD_RESPONSE_PROTO",
+        ::Protobuf::Socketrpc::ErrorReason::UNKNOWN_HOST => "UNKNOWN_HOST",
+        ::Protobuf::Socketrpc::ErrorReason::IO_ERROR => "IO_ERROR",
+      }.freeze
+
       def initialize(mode = :SERVER)
         @mode = mode
         @request_size = 0
@@ -78,6 +92,12 @@ def client?
         @mode == :CLIENT
       end
 
+      def status_string
+        return "OK" if status.nil?
+
+        ERROR_TRANSLATIONS.fetch(status, "UNKNOWN_ERROR")
+      end
+
       def to_s
         [
           server? ? "[SRV]" : "[CLT]",
@@ -86,14 +106,14 @@ def to_s
           rpc,
           sizes,
           elapsed_time,
+          status_string,
           @end_time.try(:iso8601),
         ].compact.join(' - ')
       end
 
       def trace_id
         ::Thread.current.object_id.to_s(16)
       end
-
     end
   end
 end

spec/lib/protobuf/rpc/connectors/base_spec.rb

@@ -187,14 +187,14 @@
   shared_examples "a ConnectorDisposition" do |meth, cb, *args|
 
     it "calls #complete before exit" do
-      subject.stats = double("Object", :stop => true)
+      subject.stats = ::Protobuf::Rpc::Stat.new(:stop => true)
 
       expect(subject).to receive(:complete)
       subject.method(meth).call(*args)
     end
 
     it "calls the #{cb} callback when provided" do
-      stats = double("Object")
+      stats = ::Protobuf::Rpc::Stat.new
       allow(stats).to receive(:stop).and_return(true)
       subject.stats = stats
       some_cb = double("Object")
@@ -205,7 +205,7 @@
     end
 
     it "calls the complete callback when provided" do
-      stats = double("Object")
+      stats = ::Protobuf::Rpc::Stat.new
       allow(stats).to receive(:stop).and_return(true)
       subject.stats = stats
       comp_cb = double("Object")
@@ -217,8 +217,8 @@
 
   end
 
-  it_behaves_like("a ConnectorDisposition", :failure, "failure_cb", "code", "message")
-  it_behaves_like("a ConnectorDisposition", :failure, "complete_cb", "code", "message")
+  it_behaves_like("a ConnectorDisposition", :failure, "failure_cb", :RPC_ERROR, "message")
+  it_behaves_like("a ConnectorDisposition", :failure, "complete_cb", :RPC_ERROR, "message")
   it_behaves_like("a ConnectorDisposition", :succeed, "complete_cb", "response")
   it_behaves_like("a ConnectorDisposition", :succeed, "success_cb", "response")
   it_behaves_like("a ConnectorDisposition", :complete, "complete_cb")

spec/lib/protobuf/rpc/stat_spec.rb

@@ -33,7 +33,7 @@
 
         ::Timecop.freeze(1.62.seconds.from_now) do
           stats.stop
-          expect(stats.to_s).to eq "[SRV] - myserver1 - #{stats.trace_id} - BarService#find_bars - 43B/1302B - 1.62s - #{::Time.now.iso8601}"
+          expect(stats.to_s).to eq "[SRV] - myserver1 - #{stats.trace_id} - BarService#find_bars - 43B/1302B - 1.62s - OK - #{::Time.now.iso8601}"
         end
       end
     end
@@ -44,7 +44,7 @@
         stats.client = 'myserver1'
         stats.dispatcher = double('dispatcher', :service => BarService.new(:find_bars))
         stats.request_size = 43
-        expect(stats.to_s).to eq "[SRV] - myserver1 - #{stats.trace_id} - BarService#find_bars - 43B/-"
+        expect(stats.to_s).to eq "[SRV] - myserver1 - #{stats.trace_id} - BarService#find_bars - 43B/- - OK"
       end
     end
   end
@@ -61,20 +61,39 @@
 
         ::Timecop.freeze(0.832.seconds.from_now) do
           stats.stop
-          expect(stats.to_s).to eq "[CLT] - myserver1.myhost.com:30000 - #{stats.trace_id} - Foo::BarService#find_bars - 37B/12345B - 0.832s - #{::Time.now.iso8601}"
+          expect(stats.to_s).to eq "[CLT] - myserver1.myhost.com:30000 - #{stats.trace_id} - Foo::BarService#find_bars - 37B/12345B - 0.832s - OK - #{::Time.now.iso8601}"
         end
 
       end
     end
 
+    describe 'error log' do
+      it 'resolves error to a string' do
+        ::Timecop.freeze(10.minutes.ago) do
+          stats = ::Protobuf::Rpc::Stat.new(:CLIENT)
+          stats.server = ['30000', 'myserver1.myhost.com']
+          stats.service = 'Foo::BarService'
+          stats.status = ::Protobuf::Socketrpc::ErrorReason::RPC_ERROR
+          stats.method_name = 'find_bars'
+          stats.request_size = 37
+          stats.response_size = 12345
+
+          ::Timecop.freeze(0.832.seconds.from_now) do
+            stats.stop
+            expect(stats.to_s).to eq "[CLT] - myserver1.myhost.com:30000 - #{stats.trace_id} - Foo::BarService#find_bars - 37B/12345B - 0.832s - RPC_ERROR - #{::Time.now.iso8601}"
+          end
+        end
+      end
+    end
+
     context 'when request is still running' do
       it 'omits response size, duration, and timestamp' do
         stats = ::Protobuf::Rpc::Stat.new(:CLIENT)
         stats.server = ['30000', 'myserver1.myhost.com']
         stats.service = 'Foo::BarService'
         stats.method_name = 'find_bars'
         stats.request_size = 37
-        expect(stats.to_s).to eq "[CLT] - myserver1.myhost.com:30000 - #{stats.trace_id} - Foo::BarService#find_bars - 37B/-"
+        expect(stats.to_s).to eq "[CLT] - myserver1.myhost.com:30000 - #{stats.trace_id} - Foo::BarService#find_bars - 37B/- - OK"
       end
     end
   end