diff --git a/CHANGELOG.md b/CHANGELOG.md index a86f90688d..53c810d3c7 100644 --- a/CHANGELOG.md +++ b/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. `#`) 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`** diff --git a/lib/new_relic/agent/http_clients/abstract.rb b/lib/new_relic/agent/http_clients/abstract.rb index edbeddb490..0e90076a1a 100644 --- a/lib/new_relic/agent/http_clients/abstract.rb +++ b/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 diff --git a/lib/new_relic/agent/http_clients/curb_wrappers.rb b/lib/new_relic/agent/http_clients/curb_wrappers.rb index c5e829c0a3..5c3d835dec 100644 --- a/lib/new_relic/agent/http_clients/curb_wrappers.rb +++ b/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 diff --git a/lib/new_relic/agent/http_clients/excon_wrappers.rb b/lib/new_relic/agent/http_clients/excon_wrappers.rb index ce65a5fcb3..6dc7653419 100644 --- a/lib/new_relic/agent/http_clients/excon_wrappers.rb +++ b/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 diff --git a/lib/new_relic/agent/http_clients/http_rb_wrappers.rb b/lib/new_relic/agent/http_clients/http_rb_wrappers.rb index 5ad7d6fa43..b0b041523d 100644 --- a/lib/new_relic/agent/http_clients/http_rb_wrappers.rb +++ b/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 diff --git a/lib/new_relic/agent/http_clients/httpclient_wrappers.rb b/lib/new_relic/agent/http_clients/httpclient_wrappers.rb index 578df4758c..8301f4c1ff 100644 --- a/lib/new_relic/agent/http_clients/httpclient_wrappers.rb +++ b/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 diff --git a/lib/new_relic/agent/http_clients/net_http_wrappers.rb b/lib/new_relic/agent/http_clients/net_http_wrappers.rb index ecf46ebbcd..2ea302e531 100644 --- a/lib/new_relic/agent/http_clients/net_http_wrappers.rb +++ b/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 diff --git a/lib/new_relic/agent/http_clients/typhoeus_wrappers.rb b/lib/new_relic/agent/http_clients/typhoeus_wrappers.rb index c98b06fd20..e9127df567 100644 --- a/lib/new_relic/agent/http_clients/typhoeus_wrappers.rb +++ b/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 diff --git a/lib/new_relic/agent/transaction/distributed_tracer.rb b/lib/new_relic/agent/transaction/distributed_tracer.rb index 198428efbe..8df7299b74 100644 --- a/lib/new_relic/agent/transaction/distributed_tracer.rb +++ b/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) diff --git a/test/agent_helper.rb b/test/agent_helper.rb index c8e80b5221..aae24ca439 100644 --- a/test/agent_helper.rb +++ b/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) diff --git a/test/new_relic/agent/transaction/distributed_tracer_test.rb b/test/new_relic/agent/transaction/distributed_tracer_test.rb index ca46f50727..af94e15557 100644 --- a/test/new_relic/agent/transaction/distributed_tracer_test.rb +++ b/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 diff --git a/test/new_relic/http_client_test_cases.rb b/test/new_relic/http_client_test_cases.rb index 507a64e68e..d506f83303 100644 --- a/test/new_relic/http_client_test_cases.rb +++ b/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