Merge pull request #1839 from newrelic/log-request-headers

Log request headers

CHANGELOG.md

@@ -2,13 +2,17 @@
 
 ## dev
 
-  Upcoming version removes Distributed Tracing warnings from agent logs when using Sidekiq.
+  Upcoming version removes Distributed Tracing warnings from agent logs when using Sidekiq and fixes a bug regarding logged request headers.
 
 
-- **Removes Distributed Tracing related warnings from agent logs when headers are not present in Sidekiq**
+- **Bugfix: Removes Distributed Tracing related warnings from agent logs when headers are not present in Sidekiq**
 
   Previously, the agent would log a warning to `newrelic_agent.log` every time it attempted to accept empty Distributed Tracing headers from Sidekiq jobs which could result in an excessive number of warnings. Now the agent will no longer create these warnings when using Sidekiq. [PR#1834](https://github.com/newrelic/newrelic-ruby-agent/pull/1834)
 
+- **Bugfix: Log request headers in debug-level logs instead of human-readable Objects**
+
+  Previously, the agent sometimes received children of the `NewRelic::Agent::HTTPClients::AbstractRequest` class as an argument when `NewRelic::Agent::Transaction::DistributedTracers#log_request_headers` was called. This caused debug-level log messages that print the request headers to show human-readable Objects (ex. `#<NewRelic::Agent::HTTPClients::HTTPClientRequest:0x00007fd0dda983e0>`) instead of the request headers. Now, the hash of the request headers should always be logged. [PR#1839](https://github.com/newrelic/newrelic-ruby-agent/pull/1839)
+
 ## v9.0.0
 
   Version 9.0.0 of the agent removes several deprecated configuration options and API methods, enables Thread tracing by default, adds Fiber instrumentation, removes support for Ruby versions 2.2 and 2.3, removes instrumentation for several deprecated gems, changes how the API method `set_transaction_name` works, and updates `rails_defer_initialization` to be an environment variable only configuration option.
@@ -101,8 +105,8 @@
     - HttpClient: 2.2.0 - 2.8.0
     - HttpRb: 0.9.9 - 2.2.1
     - Typhoeus: 0.5.3 - 1.2.x
-    - Bunny: 2.0.x - 2.6.x 
-    - ActiveMerchant: 1.25.0 - 1.64.x 
+    - Bunny: 2.0.x - 2.6.x
+    - ActiveMerchant: 1.25.0 - 1.64.x
 
 
 - **Updated API method `set_transaction_name`**

lib/new_relic/agent/http_clients/abstract.rb

@@ -14,28 +14,16 @@ module HTTPClients
       #
       # @api public
       class AbstractRequest
-        def []
-          raise NotImplementedError, MUST_IMPLEMENT_ERROR % [self.class, __method__]
-        end
-
-        def []=
-          raise NotImplementedError, MUST_IMPLEMENT_ERROR % [self.class, __method__]
-        end
-
-        def type
-          raise NotImplementedError, MUST_IMPLEMENT_ERROR % [self.class, __method__]
-        end
-
-        def host_from_header
-          raise NotImplementedError, MUST_IMPLEMENT_ERROR % [self.class, __method__]
+        %i[[] []= type host_from_header host method headers uri].each do |name|
+          define_method(name) do
+            not_implemented(name)
+          end
         end
 
-        def host
-          raise NotImplementedError, MUST_IMPLEMENT_ERROR % [self.class, __method__]
-        end
+        private
 
-        def method
-          raise NotImplementedError, MUST_IMPLEMENT_ERROR % [self.class, __method__]
+        def not_implemented(method_name)
+          raise NotImplementedError, MUST_IMPLEMENT_ERROR % [self.class, method_name]
         end
       end
 

lib/new_relic/agent/http_clients/curb_wrappers.rb

@@ -33,16 +33,20 @@ def method
         end
 
         def [](key)
-          @curlobj.headers[key]
+          headers[key]
         end
 
         def []=(key, value)
-          @curlobj.headers[key] = value
+          headers[key] = value
         end
 
         def uri
           @uri ||= URIUtil.parse_and_normalize_url(@curlobj.url)
         end
+
+        def headers
+          @curlobj.headers
+        end
       end
 
       class CurbResponse < AbstractResponse

lib/new_relic/agent/http_clients/excon_wrappers.rb

@@ -65,7 +65,6 @@ def type
         end
 
         def host_from_header
-          headers = @datum[:headers]
           if hostname = (headers[LHOST] || headers[UHOST])
             hostname.split(COLON).first
           end
@@ -76,18 +75,21 @@ def host
         end
 
         def [](key)
-          @datum[:headers][key]
+          headers[key]
         end
 
         def []=(key, value)
-          @datum[:headers] ||= {}
-          @datum[:headers][key] = value
+          headers[key] = value
         end
 
         def uri
           url = "#{@scheme}://#{host}:#{@port}#{@path}"
           URIUtil.parse_and_normalize_url(url)
         end
+
+        def headers
+          @datum[:headers]
+        end
       end
     end
   end

lib/new_relic/agent/http_clients/http_rb_wrappers.rb

@@ -56,6 +56,10 @@ def [](key)
         def []=(key, value)
           @wrapped_request.headers[key] = value
         end
+
+        def headers
+          @wrapped_request.headers.to_hash
+        end
       end
     end
   end

lib/new_relic/agent/http_clients/httpclient_wrappers.rb

@@ -57,12 +57,16 @@ def uri
         end
 
         def [](key)
-          request.headers[key]
+          headers[key]
         end
 
         def []=(key, value)
           request.http_header[key] = value
         end
+
+        def headers
+          request.headers
+        end
       end
     end
   end

lib/new_relic/agent/http_clients/net_http_wrappers.rb

@@ -71,6 +71,10 @@ def uri
             )
           end
         end
+
+        def headers
+          @request.instance_variable_get(:@header)
+        end
       end
     end
   end

lib/new_relic/agent/http_clients/typhoeus_wrappers.rb

@@ -66,14 +66,17 @@ def method
         end
 
         def [](key)
-          return nil unless @request.options && @request.options[:headers]
+          return nil unless @request.options && headers
 
-          @request.options[:headers][key]
+          headers[key]
         end
 
         def []=(key, value)
-          @request.options[:headers] ||= {}
-          @request.options[:headers][key] = value
+          headers[key] = value
+        end
+
+        def headers
+          @request.options[:headers] || {}
         end
 
         def uri

lib/new_relic/agent/transaction/distributed_tracer.rb

@@ -69,7 +69,8 @@ def append_payload(payload)
         end
 
         def log_request_headers(headers, direction = "OUTGOING")
-          NewRelic::Agent.logger.debug("#{direction} REQUEST HEADERS: #{headers}")
+          printed_headers = headers.is_a?(NewRelic::Agent::HTTPClients::AbstractRequest) ? headers.headers : headers
+          NewRelic::Agent.logger.debug("#{direction} REQUEST HEADERS: #{printed_headers}")
         end
 
         def insert_headers(headers)

test/agent_helper.rb

@@ -111,7 +111,8 @@ def assert_equal_unordered(left, right)
 def assert_log_contains(log, message)
   lines = log.array
 
-  assert (lines.any? { |line| line.match(message) })
+  assert (lines.any? { |line| line.match(message) }),
+    "Could not find message. Log contained: #{lines.join("\n")}"
 end
 
 def assert_audit_log_contains(audit_log_contents, needle)

test/new_relic/agent/transaction/distributed_tracer_test.rb

@@ -166,6 +166,37 @@ def tests_outbound_distributed_trace_headers_omitted_when_exclude_is_true
           end
         end
       end
+
+      def test_log_request_headers_with_hash_argument
+        test_header = {'Snow' => 'Day'}
+        log = with_array_logger(level = :debug) do
+          in_transaction do |txn|
+            txn.distributed_tracer.log_request_headers(test_header)
+          end
+        end
+
+        assert_log_contains(log, /REQUEST HEADERS: #{test_header}/)
+      end
+
+      def test_log_request_headers_with_request_argument
+        skip_unless_minitest5_or_above
+
+        test_header = {'Test' => 'Header'}
+        request = MiniTest::Mock.new
+
+        request.expect :headers, test_header
+        request.expect :is_a?, true, [NewRelic::Agent::HTTPClients::AbstractRequest]
+
+        log = with_array_logger(level = :debug) do
+          in_transaction do |txn|
+            txn.distributed_tracer.log_request_headers(request)
+          end
+        end
+
+        assert_log_contains(log, /REQUEST HEADERS: #{test_header}/)
+
+        request.verify
+      end
     end
   end
 end

test/new_relic/http_client_test_cases.rb

@@ -73,6 +73,7 @@ def test_validate_request_wrapper
     req = request_instance
 
     assert_implements req, :type
+    assert_implements req, :headers
     assert_implements req, :host
     assert_implements req, :host_from_header
     assert_implements req, :method
@@ -97,6 +98,15 @@ def test_status_code_is_present
     assert_equal 200, res.status_code
   end
 
+  def test_request_headers
+    header_key = 'Honolooploop'
+    instance = request_instance
+    instance[header_key] = 'Charles Petrescu'
+
+    assert instance.headers.is_a?(Hash)
+    assert instance.headers.any? { |k, v| k.casecmp?(header_key) }
+  end
+
   # Some libraries (older Typhoeus), have had odd behavior around [] for
   # missing keys. This generates log messages, although it behaves right in
   # terms of metrics, so double-check we get what we expect