fix(datadog) skip non-matched apis #2702

kjsteuer · 2017-07-16T02:30:43Z

Fix runtime error when the datadog plugin is global and there is
not a catch all api present

Summary

Addresses the runtime error that occurs when datadog is registered as a global plugin and there is not a catch all api.

Example log:
2017/07/06 01:41:53 [error] 101#0: *60797 lua entry thread aborted: runtime error: /usr/local/share/lua/5.1/kong/plugins/datadog/handler.lua:60: attempt to index field 'api' (a nil value)]

cc @p0pr0ck5

kjsteuer · 2017-07-16T02:33:18Z

kong/plugins/datadog/handler.lua

@@ -53,6 +53,11 @@ local function log(premature, conf, message)
  if premature then
    return
  end
+
+  if message.api == nil then -- unmatched apis are nil
+    return


I was originally thinking to have a warn log here, however, that would probably be expected and spammy for many.

thibaultcha · 2017-07-16T02:55:10Z

Hi, thanks for the patch. Could you provide a regression test for this as well?

kjsteuer · 2017-07-16T19:24:01Z

@thibaultcha I may need some help getting the tests to work. From manually testing I know this works.

Since the error results in a log error only, I am not able to test from the outside.

Here is what I tried:

adding a global plugin

    assert(helpers.dao.plugins:insert {
      name = "datadog",
      config = {
        host = "127.0.0.1",
        port = 9999,
        metrics = "request_count,status_count,latency",
        tags = {
          request_count = {"T1:V1"},
          status_count = {"T2:V2,T3:V3,T4"},
          latency = {"T2:V2:V3,T4"},
        }
      }
    })

adding the following test:

it("should not return a guage", function()
    local thread = threads.new({
      function()
        local socket = require "socket"
        local server = assert(socket.udp())
        server:settimeout(1)
        server:setoption("reuseaddr", true)
        server:setsockname("127.0.0.1", 9999)
        gauge = server:receive()
        server:close()
        return gauge
      end
    })
    thread:start()

    local res = assert(client:send {
      method = "GET",
      path = "/NonMatching",
      headers = {
        ["Host"] = "datadog3.com"
      }
    })
    assert.res_status(404, res)

    local ok, gauge = thread:join()
    assert.True(guage == nil)
  end)

However, this succeeds even without my change because error is an internal log problem vs exposed externally.

Is there a way to test calling the log method directly from the spec?

p0pr0ck5 · 2017-07-17T16:14:24Z

@kjsteuer since the fix here relates to an error message printed in the Nginx error log, you could write an assertion that the contents of the mock Kong error log do not contain the error message noted above? I don't think this is a pattern we employ anywhere else in our tests, but since we are testing for behavior in a ngx.timer context, examining the contents of the mock gauge object isn't useful (as you've noted).

thibaultcha · 2017-07-17T17:00:48Z

@kjsteuer We use a - somewhat - similar approach in the file-log plugin tests. You can draw inspiration from there. Our future "Kong test framework" will have facilities to write such assertions out of the box, but in the meanwhile, this is the only approach. Sorry!

kjsteuer · 2017-07-18T00:24:08Z

@thibaultcha @p0pr0ck5 how do I reference the error log?

I tried the following, however, the log signature is different than above. Do I have the wrong error logs?

  it("should not return a runtime error (regression)", function()
    local thread = threads.new({
      function()
        local socket = require "socket"
        local server = assert(socket.udp())
        server:settimeout(1)
        server:setoption("reuseaddr", true)
        server:setsockname("127.0.0.1", 9999)
        gauge = server:receive()
        server:close()
        return gauge
      end
    })
    thread:start()

    local res = assert(client:send {
      method = "GET",
      path = "/NonMatch",
      headers = {
        ["Host"] = "datadog3.com"
      }
    })
    assert.res_status(404, res)
    
    local err_log = pl_file.read(helpers.test_conf.nginx_err_logs)
    print(err_log)
    assert.is_nil(err_log:find("error", nil, true), "error not expected in logs")
  end)

from the print statement:

...
2017/07/18 00:20:31 [debug] 20686#0: *13 [lua] statsd_logger.lua:62: counter(): [udp-log] sending data to statsd server: kong.datadog3_com.request.status.404:1|c|#T2:V2,T3:V3,T4
2017/07/18 00:20:31 [debug] 20686#0: *13 [lua] statsd_logger.lua:62: gauge(): [udp-log] sending data to statsd server: kong.datadog3_com.latency:32|g|#T2:V2:V3,T4
2017/07/18 00:20:31 [error] 20686#0: *13 send() failed (111: Connection refused), context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9000
2017/07/18 00:20:31 [error] 20686#0: *13 [lua] statsd_logger.lua:66: gauge(): [udp-log] could not send data to 127.0.0.1:9999: connection refused, context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9000

p0pr0ck5 · 2017-07-18T00:33:55Z

@kjsteuer you have the correct log, but based on those entries, it looks like your test is actually resulting in the logger being called. Your host header is datadog3.com, which is defined as part of an API- even though the request path is /NonMatch, the host still matches, and therefore the plugin executes. Trying adjusting your client:send call to use a non-matching hostname.

kjsteuer · 2017-07-18T02:08:21Z

@p0pr0ck5 that was the issue, thanks

p0pr0ck5

Thanks @kjsteuer! I think this is almost ready for merge; just a few small comments. Also, would you mind squashing your commits into a single commit? The first commit has the appropriate commit message format. Thanks!

p0pr0ck5 · 2017-07-18T03:36:09Z

kong/plugins/datadog/handler.lua

@@ -53,6 +53,11 @@ local function log(premature, conf, message)
  if premature then
    return
  end
+
+  if message.api == nil then -- unmatched apis are nil


I think we would prefer if not message.api then... rather than the check for nil, because we only care about the truthiness of message.api (see https://github.com/Mashape/kong/blob/master/CONTRIBUTING.md#conditional-expressions).

p0pr0ck5 · 2017-07-18T03:39:58Z

spec/03-plugins/08-datadog/01-log_spec.lua

+    assert.res_status(404, res)
+
+    local err_log = pl_file.read(helpers.test_conf.nginx_err_logs)
+    assert.is_nil(err_log:find("attempt to index field 'api' (a nil value)", nil, true), "error not expected in logs")


Not a blocker for me, but just to note for consistency, we don't generally write messages in the assertion itself, but rather save informative descriptions for the describe/it blocks.

kjsteuer · 2017-07-18T19:00:11Z

Thanks @kjsteuer! I think this is almost ready for merge; just a few small comments. Also, would you mind squashing your commits into a single commit? The first commit has the appropriate commit message format. Thanks!

updated .. let me know about the new if condition if that is what you are thinking.

p0pr0ck5 · 2017-07-18T20:22:49Z

Hmmm, not quite. Your original approach was correct, it just needed to avoid the explicit check for nil. This new approach is less desirable; it's preferred to return each from a flow rather than writing "arrow code" that conditionally executes/loops. So this would probably look like (around line 56, before the statsd logger creation):

if not message.api then
  return
end

That way we don't have to touch code further down the block. Does this make sense?

thibaultcha · 2017-07-18T20:30:40Z

spec/03-plugins/08-datadog/01-log_spec.lua

+    assert.res_status(404, res)
+
+    local err_log = pl_file.read(helpers.test_conf.nginx_err_logs)
+    assert.is_nil(err_log:find("attempt to index field 'api' (a nil value)", nil, true))


I think you can use:

assert.not_matches(err_log, "attempt to index field 'api' (a nil value)", nil, true)

this doesn't seem to work. is there an equivalent to not_find or not_contains? I am not seeing any documentation for assert.not_matches but I think it is doing something different than find.

Can you define "doesn't seem to work"? We use this assertion throughout the codebase, for example:

spec/02-integration/05-proxy/01-router_spec.lua: assert.not_matches("/x/y/z/get", json.url, nil, true)

yeah, I commented out my return code out and run the following test. It should fail, however, it succeeds.

it("should not return a runtime error (regression)", function() local thread = threads.new({ function() local socket = require "socket" local server = assert(socket.udp()) server:settimeout(1) server:setoption("reuseaddr", true) server:setsockname("127.0.0.1", 9999) local gauge = server:receive() server:close() return gauge end }) thread:start() local res = assert(client:send { method = "GET", path = "/NonMatch", headers = { ["Host"] = "fakedns.com" } }) assert.res_status(404, res) local err_log = pl_file.read(helpers.test_conf.nginx_err_logs) print(err_log) assert.not_matches(err_log, "attempt to index field 'api' (a nil value)", nil, true) end)

output

vagrant@vagrant-ubuntu-trusty-64:/kong$ bin/busted -v -o gtest spec/03-plugins/08-datadog/ [==========] Running tests from scanned files. [----------] Global test environment setup. [----------] Running tests from spec/03-plugins/08-datadog/01-log_spec.lua [ RUN ] spec/03-plugins/08-datadog/01-log_spec.lua @ 79: Plugin: datadog (log) logs metrics over UDP [ OK ] spec/03-plugins/08-datadog/01-log_spec.lua @ 79: Plugin: datadog (log) logs metrics over UDP (256.73 ms) [ RUN ] spec/03-plugins/08-datadog/01-log_spec.lua @ 117: Plugin: datadog (log) logs only given metrics [ OK ] spec/03-plugins/08-datadog/01-log_spec.lua @ 117: Plugin: datadog (log) logs only given metrics (93.25 ms) [ RUN ] spec/03-plugins/08-datadog/01-log_spec.lua @ 151: Plugin: datadog (log) logs metrics with tags [ OK ] spec/03-plugins/08-datadog/01-log_spec.lua @ 151: Plugin: datadog (log) logs metrics with tags (66.23 ms) [ RUN ] spec/03-plugins/08-datadog/01-log_spec.lua @ 186: Plugin: datadog (log) should not return a runtime error (regression) 2017/07/19 16:30:59 [debug] 10410#0: [lua] globalpatches.lua:9: installing the globalpatches 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:73: load_plugins(): Discovering used plugins 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: syslog 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: ldap-auth 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: rate-limiting 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: correlation-id 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: jwt 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: request-termination 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: runscope 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: request-transformer 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: http-log 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: loggly 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: response-transformer 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: basic-auth 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: tcp-log 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: hmac-auth 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: oauth2 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: acl 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: bot-detection 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: udp-log 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: cors 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: file-log 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: ip-restriction 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: datadog 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: request-size-limiting 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: galileo 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: aws-lambda 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: statsd 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: response-ratelimiting 2017/07/19 16:30:59 [debug] 10410#0: [lua] kong.lua:101: load_plugins(): Loading plugin: key-auth 2017/07/19 16:30:59 [notice] 10410#0: using the "epoll" event method 2017/07/19 16:30:59 [notice] 10410#0: openresty/1.11.2.2 2017/07/19 16:30:59 [notice] 10410#0: built by gcc 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) 2017/07/19 16:30:59 [notice] 10410#0: OS: Linux 3.13.0-123-generic 2017/07/19 16:30:59 [notice] 10410#0: getrlimit(RLIMIT_NOFILE): 65535:65535 2017/07/19 16:30:59 [notice] 10423#0: start worker processes 2017/07/19 16:30:59 [notice] 10423#0: start worker process 10425 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] globalpatches.lua:219: randomseed(): seeding PRNG from OpenSSL RAND_bytes() 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] globalpatches.lua:245: randomseed(): random seed: 135120151132 for worker nb 0 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "bot-detection": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "cors": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "jwt": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "oauth2": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "key-auth": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "ldap-auth": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "basic-auth": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "hmac-auth": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "ip-restriction": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "request-size-limiting": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "acl": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "rate-limiting": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "response-ratelimiting": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "request-transformer": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "response-transformer": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "aws-lambda": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "http-log": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "statsd": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "datadog": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "file-log": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "udp-log": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "request-termination": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "loggly": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "runscope": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "syslog": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "galileo": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "tcp-log": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *1 [lua] base_plugin.lua:12: init_worker(): executing plugin "correlation-id": init_worker 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] client.lua:483: lookup(): [dns-client] bad ipv4 query: '127.0.0.1' with type 33 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] client.lua:472: lookup(): [dns-client] ipv4 query: '127.0.0.1' with type 1 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:20: rewrite(): executing plugin "datadog": rewrite 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:24: access(): executing plugin "datadog": access 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] balancer.lua:33: cb(): fetching all upstreams 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] client.lua:531: lookup(): [dns-client] querying 'mockbin.com' for type 33 took 63.999891281128 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] client.lua:574: lookup(): [dns-client] querying 'mockbin.com' for type 33: entries 0 error nil nil 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] client.lua:531: lookup(): [dns-client] querying 'mockbin.com' for type 1 took 58.000087738037 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] client.lua:574: lookup(): [dns-client] querying 'mockbin.com' for type 1: entries 2 error nil nil 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:28: header_filter(): executing plugin "datadog": header_filter 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:32: body_filter(): executing plugin "datadog": body_filter 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:32: body_filter(): executing plugin "datadog": body_filter 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:36: log(): executing plugin "datadog": log 2017/07/19 16:30:59 [debug] 10425#0: *6 [lua] statsd_logger.lua:62: counter(): [udp-log] sending data to statsd server: kong.datadog1_com.request.count:1|c 2017/07/19 16:30:59 [debug] 10425#0: *6 [lua] statsd_logger.lua:62: gauge(): [udp-log] sending data to statsd server: kong.datadog1_com.latency:245|g 2017/07/19 16:30:59 [debug] 10425#0: *6 [lua] statsd_logger.lua:62: gauge(): [udp-log] sending data to statsd server: kong.datadog1_com.request.size:101|g 2017/07/19 16:30:59 [debug] 10425#0: *6 [lua] statsd_logger.lua:62: counter(): [udp-log] sending data to statsd server: kong.datadog1_com.request.status.200:1|c 2017/07/19 16:30:59 [debug] 10425#0: *6 [lua] statsd_logger.lua:62: gauge(): [udp-log] sending data to statsd server: kong.datadog1_com.response.size:878|g 2017/07/19 16:30:59 [debug] 10425#0: *6 [lua] statsd_logger.lua:62: gauge(): [udp-log] sending data to statsd server: kong.datadog1_com.upstream_latency:98|g 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:20: rewrite(): executing plugin "datadog": rewrite 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:24: access(): executing plugin "datadog": access 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:28: header_filter(): executing plugin "datadog": header_filter 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:32: body_filter(): executing plugin "datadog": body_filter 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:32: body_filter(): executing plugin "datadog": body_filter 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:36: log(): executing plugin "datadog": log 2017/07/19 16:30:59 [debug] 10425#0: *9 [lua] statsd_logger.lua:62: counter(): [udp-log] sending data to statsd server: kong.datadog2_com.request.count:1|c 2017/07/19 16:30:59 [debug] 10425#0: *9 [lua] statsd_logger.lua:62: counter(): [udp-log] sending data to statsd server: kong.datadog2_com.request.status.200:1|c 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:20: rewrite(): executing plugin "datadog": rewrite 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:24: access(): executing plugin "datadog": access 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:28: header_filter(): executing plugin "datadog": header_filter 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:32: body_filter(): executing plugin "datadog": body_filter 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:32: body_filter(): executing plugin "datadog": body_filter 2017/07/19 16:30:59 [debug] 10425#0: *2 [lua] base_plugin.lua:36: log(): executing plugin "datadog": log 2017/07/19 16:30:59 [debug] 10425#0: *11 [lua] statsd_logger.lua:62: counter(): [udp-log] sending data to statsd server: kong.datadog3_com.request.count:1|c|#T1:V1 2017/07/19 16:30:59 [debug] 10425#0: *11 [lua] statsd_logger.lua:62: counter(): [udp-log] sending data to statsd server: kong.datadog3_com.request.status.200:1|c|#T2:V2,T3:V3,T4 2017/07/19 16:30:59 [debug] 10425#0: *11 [lua] statsd_logger.lua:62: gauge(): [udp-log] sending data to statsd server: kong.datadog3_com.latency:58|g|#T2:V2:V3,T4 2017/07/19 16:31:00 [debug] 10425#0: *2 [lua] base_plugin.lua:20: rewrite(): executing plugin "datadog": rewrite 2017/07/19 16:31:00 [debug] 10425#0: *2 [lua] base_plugin.lua:28: header_filter(): executing plugin "datadog": header_filter 2017/07/19 16:31:00 [debug] 10425#0: *2 [lua] base_plugin.lua:32: body_filter(): executing plugin "datadog": body_filter 2017/07/19 16:31:00 [debug] 10425#0: *2 [lua] base_plugin.lua:32: body_filter(): executing plugin "datadog": body_filter 2017/07/19 16:31:00 [debug] 10425#0: *2 [lua] base_plugin.lua:36: log(): executing plugin "datadog": log 2017/07/19 16:31:00 [error] 10425#0: *13 lua entry thread aborted: runtime error: ./kong/plugins/datadog/handler.lua:67: attempt to index field 'api' (a nil value) stack traceback: coroutine 0: ./kong/plugins/datadog/handler.lua: in function <./kong/plugins/datadog/handler.lua:52>, context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9000 [ OK ] spec/03-plugins/08-datadog/01-log_spec.lua @ 186: Plugin: datadog (log) should not return a runtime error (regression) (9.41 ms) [----------] 4 tests from spec/03-plugins/08-datadog/01-log_spec.lua (1864.43 ms total) [----------] Global test environment teardown. [==========] 4 tests from 1 test file ran. (1865.32 ms total) [ PASSED ] 4 tests.

I also tried something more simple like assert.not_matches(err_log, "attempt to index field", nil, true), however, that also succeeds when it should fail.

kjsteuer · 2017-07-18T20:51:29Z

That way we don't have to touch code further down the block. Does this make sense?
👍 1

yeah, I didn't like it, however, I didn't know about the not checks in lua, my first lua commit ;)

p0pr0ck5 · 2017-07-28T06:53:25Z

@kjsteuer any update on getting the tests updated? @thibaultcha is this a blocker for you?

kjsteuer · 2017-07-28T13:58:20Z

@kjsteuer any update on getting the tests updated? @thibaultcha is this a blocker for you?

@p0pr0ck5 yeah, I wasn't able to get the assert.not_matches(err_log, "attempt to index field 'api' (a nil value)", nil, true) line to fail prior to the change. Further details above in the comment. Happy to make updates here, I am just stuck on the recommendation.

p0pr0ck5 · 2017-08-02T15:36:13Z

@kjsteuer sorry for the delay over here. Looks like the suggestion from @thibaultcha was slightly off, the first two params in the not_matches assertion need to be switched. Have a look at https://github.com/Mashape/kong/tree/fix/datadog-unmatched-apis (this will fail prior to your change).

p0pr0ck5 · 2017-08-02T15:36:40Z

kong/plugins/datadog/handler.lua

@@ -53,6 +53,11 @@ local function log(premature, conf, message)
  if premature then
    return
  end
+
+  if not message.api then -- unmatched apis are nil


minor style nitpick, can we place the comment on the previous line instead of adjacent to the code here? thanks :)

kjsteuer · 2017-08-03T12:16:14Z

@kjsteuer sorry for the delay over here. Looks like the suggestion from @thibaultcha was slightly off, the first two params in the not_matches assertion need to be switched. Have a look at https://github.com/Mashape/kong/tree/fix/datadog-unmatched-apis (this will fail prior to your change).

That was it, thank you. PR updated

kjsteuer · 2017-08-03T12:17:14Z

@p0pr0ck5 I noticed #2758 . What is the difference between the statsd / datadog plugins? Curious if they can be combined since the logic is so similar.

p0pr0ck5 · 2017-08-03T20:38:21Z

@p0pr0ck5 I noticed #2758 . What is the difference between the statsd / datadog plugins? Curious if they can be combined since the logic is so similar.

@shashiranjan84, would you be able to provide some insight here? I think you're a bit more familiar with this than I am.

p0pr0ck5

Thanks for working on this @kjsteuer! I think we're close to merging this; I just have one though on where we should put this logic check.

p0pr0ck5 · 2017-08-03T20:40:52Z

kong/plugins/datadog/handler.lua

@@ -53,6 +53,12 @@ local function log(premature, conf, message)
  if premature then
    return
  end
+
+  -- unmatched apis are nil


On thinking through this, I think it's more sane to put this gate in the :log phase handler, rather than this local function. Doing so would mean we don't need to needlessly spend the resources to launch a timer event when we know we're just going to bail out.

We can probably put such a gate before the call to basic_serializer.serialze, as we don't need that overhead either; we can simply check for the existing for ngx.ctx.api as you've done here with message.api.

@p0pr0ck5 great call, updated

shashiranjan84 · 2017-08-03T20:43:18Z

@kjsteuer You are right, it is exactly same except the tagging support in Datatog. They are also separate plugin because of some business reasons and currently we don't any plan to merge them.

Fix runtime error when the datadog plugin is global and there is not a catch all api present

p0pr0ck5 · 2017-08-07T03:32:43Z

Thanks @kjsteuer! Merged!

kjsteuer commented Jul 16, 2017

View reviewed changes

p0pr0ck5 added the pr/changes requested Changes were requested to this PR by a maintainer. Please address them and ping back once done. label Jul 17, 2017

p0pr0ck5 added pr/status/please review and removed pr/changes requested Changes were requested to this PR by a maintainer. Please address them and ping back once done. labels Jul 18, 2017

p0pr0ck5 suggested changes Jul 18, 2017

View reviewed changes

p0pr0ck5 added pr/changes requested Changes were requested to this PR by a maintainer. Please address them and ping back once done. and removed pr/status/please review labels Jul 18, 2017

kjsteuer force-pushed the master branch from ded1265 to 910fdd2 Compare July 18, 2017 18:56

thibaultcha reviewed Jul 18, 2017

View reviewed changes

kjsteuer force-pushed the master branch from 910fdd2 to 0f8750f Compare July 18, 2017 21:33

thibaultcha added pr/status/please review and removed pr/changes requested Changes were requested to this PR by a maintainer. Please address them and ping back once done. labels Jul 22, 2017

p0pr0ck5 reviewed Aug 2, 2017

View reviewed changes

p0pr0ck5 added pr/changes requested Changes were requested to this PR by a maintainer. Please address them and ping back once done. and removed pr/status/please review labels Aug 2, 2017

p0pr0ck5 mentioned this pull request Aug 2, 2017

fix(statsd) deal with nil ctx.api on 404 #2758

Closed

kjsteuer force-pushed the master branch from 0f8750f to 3b65e8b Compare August 3, 2017 12:14

p0pr0ck5 added pr/status/please review and removed pr/changes requested Changes were requested to this PR by a maintainer. Please address them and ping back once done. labels Aug 3, 2017

p0pr0ck5 suggested changes Aug 3, 2017

View reviewed changes

kjsteuer force-pushed the master branch 3 times, most recently from 90b987f to 2dfdf70 Compare August 6, 2017 12:22

fix(datadog) skip non-matched apis

3a56283

Fix runtime error when the datadog plugin is global and there is not a catch all api present

kjsteuer force-pushed the master branch from 2dfdf70 to 3a56283 Compare August 6, 2017 12:23

p0pr0ck5 approved these changes Aug 7, 2017

View reviewed changes

p0pr0ck5 merged commit 0431f18 into Kong:master Aug 7, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix(datadog) skip non-matched apis #2702

fix(datadog) skip non-matched apis #2702

kjsteuer commented Jul 16, 2017

kjsteuer Jul 16, 2017

thibaultcha commented Jul 16, 2017

kjsteuer commented Jul 16, 2017

p0pr0ck5 commented Jul 17, 2017

thibaultcha commented Jul 17, 2017

kjsteuer commented Jul 18, 2017

p0pr0ck5 commented Jul 18, 2017

kjsteuer commented Jul 18, 2017

p0pr0ck5 left a comment

p0pr0ck5 Jul 18, 2017

p0pr0ck5 Jul 18, 2017

kjsteuer commented Jul 18, 2017

p0pr0ck5 commented Jul 18, 2017

thibaultcha Jul 18, 2017

kjsteuer Jul 18, 2017

p0pr0ck5 Jul 19, 2017

kjsteuer Jul 19, 2017 •

edited

Loading

kjsteuer Jul 19, 2017

kjsteuer commented Jul 18, 2017

p0pr0ck5 commented Jul 28, 2017

kjsteuer commented Jul 28, 2017

p0pr0ck5 commented Aug 2, 2017

p0pr0ck5 Aug 2, 2017

kjsteuer commented Aug 3, 2017

kjsteuer commented Aug 3, 2017

p0pr0ck5 commented Aug 3, 2017

p0pr0ck5 left a comment

p0pr0ck5 Aug 3, 2017

kjsteuer Aug 6, 2017

shashiranjan84 commented Aug 3, 2017

p0pr0ck5 commented Aug 7, 2017

fix(datadog) skip non-matched apis #2702

fix(datadog) skip non-matched apis #2702

Conversation

kjsteuer commented Jul 16, 2017

Summary

Choose a reason for hiding this comment

thibaultcha commented Jul 16, 2017

kjsteuer commented Jul 16, 2017

p0pr0ck5 commented Jul 17, 2017

thibaultcha commented Jul 17, 2017

kjsteuer commented Jul 18, 2017

p0pr0ck5 commented Jul 18, 2017

kjsteuer commented Jul 18, 2017

p0pr0ck5 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kjsteuer commented Jul 18, 2017

p0pr0ck5 commented Jul 18, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kjsteuer Jul 19, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kjsteuer commented Jul 18, 2017

p0pr0ck5 commented Jul 28, 2017

kjsteuer commented Jul 28, 2017

p0pr0ck5 commented Aug 2, 2017

Choose a reason for hiding this comment

kjsteuer commented Aug 3, 2017

kjsteuer commented Aug 3, 2017

p0pr0ck5 commented Aug 3, 2017

p0pr0ck5 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

shashiranjan84 commented Aug 3, 2017

p0pr0ck5 commented Aug 7, 2017

kjsteuer Jul 19, 2017 •

edited

Loading