search

instana / ruby-sensor

💎 Ruby Distributed Tracing & Metrics Sensor for Instana
https://www.instana.com/
MIT License
26 stars 25 forks source link

Fix exception when remove_from_query is called with nil #251

Closed fgimenezm closed 3 years ago

fgimenezm commented 3 years ago

~Only capture uri.query if it's not nil~ Fix exception when remove_from_query is called with nil fixes #250

hmadison commented 3 years ago

Hi,

Can you please make sure that this branch is tested?

Thanks, Hunter

fgimenezm commented 3 years ago

Hi @hmadison , I tried to add a test for this but the thing is the problem only happens when the ruby sensor is connected to an agent. I couldn't make a test case that shows the error without an actual Instana agent running.

If I start the app in a host without an agent I get this and the "curl" test responds OK

~/g/minimal_instana_bug_sample ❯❯❯ INSTANA_DEBUG=true bundle exec rackup                                                                                                          main
I, [2021-07-07T13:33:20.622080 #38847]  INFO -- : Stan is on the scene.  Starting Instana instrumentation version 1.203.0
D, [2021-07-07T13:33:20.741736 #38847] DEBUG -- : Waiting on a connection to the agent.
D, [2021-07-07T13:33:20.745331 #38847] DEBUG -- : Activated #<Instana::Activators::NetHTTP:0x00007fa29d898dd8>, #<Instana::Activators::Rack:0x00007fa29f17ee38>, #<Instana::Activators::Sinatra:0x00007fa28d8a8928>
[2021-07-07 13:33:20] INFO  WEBrick 1.4.4
[2021-07-07 13:33:20] INFO  ruby 2.6.7 (2021-04-05) [x86_64-darwin20]
[2021-07-07 13:33:20] INFO  WEBrick::HTTPServer#start: pid=38847 port=9292
D, [2021-07-07T13:33:21.748771 #38847] DEBUG -- : Waiting on a connection to the agent.
[...]
D, [2021-07-07T13:34:11.999578 #38847] DEBUG -- : Waiting on a connection to the agent.
::1 - - [07/Jul/2021:13:34:12 -0300] "GET / HTTP/1.1" 200 1256 0.3218
D, [2021-07-07T13:34:13.004858 #38847] DEBUG -- : Waiting on a connection to the agent.
D, [2021-07-07T13:34:14.011882 #38847] DEBUG -- : Waiting on a connection to the agent.

but when I test it with a running agent I get the error:

~/g/minimal_instana_bug_sample ❯❯❯ INSTANA_DEBUG=true bundle exec rackup                                                                                                          main
I, [2021-07-07T13:37:47.577395 #39200]  INFO -- : Stan is on the scene.  Starting Instana instrumentation version 1.203.0
D, [2021-07-07T13:37:47.710264 #39200] DEBUG -- : Activated #<Instana::Activators::NetHTTP:0x00007fc8caa12120>, #<Instana::Activators::Rack:0x00007fc8caa1a2f8>, #<Instana::Activators::Sinatra:0x00007fc8caa7bf80>
D, [2021-07-07T13:37:47.764840 #39200] DEBUG -- : Discovery complete (`{"pid"=>39200, "agentUuid"=>"14:7d:da:ff:fe:d5:d0:dd", "secrets"=>{"matcher"=>"contains-ignore-case", "list"=>["key", "pass", "secret"]}}`). Waiting for agent.
[2021-07-07 13:37:47] INFO  WEBrick 1.4.4
[2021-07-07 13:37:47] INFO  ruby 2.6.7 (2021-04-05) [x86_64-darwin20]
[2021-07-07 13:37:47] INFO  WEBrick::HTTPServer#start: pid=39200 port=9292
D, [2021-07-07T13:37:51.792457 #39200] DEBUG -- : Agent ready.
2021-07-07 13:38:01 - ArgumentError - bad argument (expected URI object or URI string):
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/uri/common.rb:739:in `URI'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/instana-1.203.0/lib/instana/secrets.rb:17:in `remove_from_query'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/instana-1.203.0/lib/instana/instrumentation/net-http.rb:39:in `request'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/net/http.rb:1380:in `request_get'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/net/http.rb:483:in `block in get_response'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/net/http.rb:920:in `start'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/net/http.rb:605:in `start'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/net/http.rb:481:in `get_response'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/net/http.rb:458:in `get'
    /Users/fgimen/gitrepos/minimal_instana_bug_sample/hello.rb:8:in `block in <top (required)>'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1675:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1675:in `block in compile!'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1013:in `block (3 levels) in route!'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1032:in `route_eval'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1013:in `block (2 levels) in route!'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1061:in `block in process_route'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1059:in `catch'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1059:in `process_route'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1011:in `block in route!'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1008:in `each'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1008:in `route!'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1129:in `block in dispatch!'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1101:in `block in invoke'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1101:in `catch'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1101:in `invoke'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1124:in `dispatch!'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:939:in `block in call!'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1101:in `block in invoke'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1101:in `catch'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1101:in `invoke'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:939:in `call!'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:929:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/instana-1.203.0/lib/instana/instrumentation/rack.rb:22:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-protection-2.1.0/lib/rack/protection/xss_header.rb:18:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-protection-2.1.0/lib/rack/protection/path_traversal.rb:16:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-protection-2.1.0/lib/rack/protection/json_csrf.rb:26:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-protection-2.1.0/lib/rack/protection/base.rb:50:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-protection-2.1.0/lib/rack/protection/base.rb:50:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-protection-2.1.0/lib/rack/protection/frame_options.rb:31:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/logger.rb:17:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:246:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/show_exceptions.rb:22:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:216:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1991:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1542:in `block in call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1769:in `synchronize'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1542:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/lint.rb:50:in `_call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/lint.rb:38:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/show_exceptions.rb:23:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/common_logger.rb:38:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:253:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/content_length.rb:17:in `call'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/handler/webrick.rb:95:in `service'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/webrick/httpserver.rb:140:in `service'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/webrick/httpserver.rb:96:in `run'
    /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/webrick/server.rb:307:in `block in start_thread'
::1 - - [07/Jul/2021:13:38:01 -0300] "GET / HTTP/1.1" 500 6793 0.2382
fgimenezm commented 3 years ago

I tried to create a "test_get_without_query" similar to the "with_query" that is here: https://github.com/instana/ruby-sensor/blob/master/test/instrumentation/net_http_test.rb#L14

But the test didn't throw an exception. I'm assuming this is because there is no agent to connect to during the test run.

hmadison commented 3 years ago

This project uses Appraisal to help manage the testing matrix. To run the test suite for Net::HTTP locally, you can use bundle exec appraisal net-http-01 bundle exec rake test.

fgimenezm commented 3 years ago

I tried that but the exception doesn't happen in the test, not sure why. In fact, the "test_block_request" test should be failing too since it has a nil query but it still passes. I've added a test that should in theory trigger the issue but for some reason it doesn't (EDIT: I mean, the test doesn't fail even with the original code without my changes)

fgimenezm commented 3 years ago

Ok, I know what's going on. The ::Instana.secrets.remove_from_query() method has this:

return str unless secret_values

and when the tests runs secret_values (which defaults to Instana.agent.secret_values) is nil so it just returns str and never hits the line that causes the actual error.

fgimenezm commented 3 years ago

@hmadison , I'm changing the direction here. Looks like the problem is not how the net/http instrumentation calls remove_from_query() but how remove_from_query() reacts if it receives "nil". I added a test to secrets_test.rb that demonstrates the issue and will propose a different fix in a minute

fgimenezm commented 3 years ago

My new secrets test without the proposed fix:

SecretsTest
  test_invalid                                                    PASS (0.00s)
  test_equals_ignore_case                                         PASS (0.00s)
  test_without_scheme                                             PASS (0.00s)
  test_without_url                                                PASS (0.00s)
  test_with_nil                                                  ERROR (0.00s)
ArgumentError:         ArgumentError: bad argument (expected URI object or URI string)
            /Users/fgimen/.rbenv/versions/2.6.7/lib/ruby/2.6.0/uri/common.rb:739:in `URI'
            /Users/fgimen/gitrepos/ruby-sensor/lib/instana/secrets.rb:17:in `remove_from_query'
            /Users/fgimen/gitrepos/ruby-sensor/test/secrets_test.rb:97:in `test_with_nil'

  test_contains                                                   PASS (0.00s)
  test_contains_ignore_case                                       PASS (0.00s)
  test_equals                                                     PASS (0.00s)
  test_regexp                                                     PASS (0.00s)

after the proposed fix:

SecretsTest
  test_contains_ignore_case                                       PASS (0.00s)
  test_equals                                                     PASS (0.00s)
  test_without_url                                                PASS (0.00s)
  test_without_scheme                                             PASS (0.00s)
  test_invalid                                                    PASS (0.00s)
  test_equals_ignore_case                                         PASS (0.00s)
  test_regexp                                                     PASS (0.00s)
  test_contains                                                   PASS (0.00s)
  test_with_nil                                                   PASS (0.00s)
fgimenezm commented 3 years ago

and the net-http tests still work ok

NetHTTPTest
  test_get_with_query                                             PASS (0.01s)
  test_request_with_5xx_response                                  PASS (0.00s)
  test_block_request                                              PASS (0.01s)
  test_config_defaults                                            PASS (0.00s)
  test_basic_post_without_uri                                     PASS (0.00s)
  test_get_without_query                                          PASS (0.00s)
  test_request_with_dns_error                                     PASS (0.01s)