fix(counters): move sales counters before plugins in log phase (#9744)

In case some errors are thrown in some plugin execution, it can cause
the `sales_counters` to fail to increase. In order to address the above
limitations, here we decide to move `sales_counters` ahead of all
`plugins` in the `log` phase.

* tests(*): add test case

* tests(*): stop the mock server in teardown for cleaning environment

* refactor(*): move analytics and sales_counters to `log.before`

kong/enterprise_edition/init.lua

@@ -144,9 +144,12 @@ _M.handlers = {
     end
   },
   log = {
+    before = function(ctx)
+      kong.analytics:log_request()
+      kong.sales_counters:log_request(ctx)
+    end,
     after = function(ctx, status)
       if not ctx.is_internal then
-        kong.sales_counters:log_request(ctx)
         if kong.vitals then
           kong.vitals:log_latency(ctx.KONG_PROXY_LATENCY)
           kong.vitals:log_request(ctx)

kong/init.lua

@@ -1949,7 +1949,7 @@ function Kong.log()
   ctx.KONG_PHASE = PHASES.log
 
   runloop.log.before(ctx)
-  kong.analytics:log_request()
+  ee.handlers.log.before(ctx)
   local plugins_iterator = runloop.get_plugins_iterator()
   execute_collected_plugins_iterator(plugins_iterator, "log", ctx)
   plugins_iterator.release(ctx)

spec-ee/02-integration/12-counters/02-metrics_spec.lua

@@ -14,86 +14,13 @@ local http_mock = require "spec.helpers.http_mock"
 for _, strategy in helpers.each_strategy() do
 
 describe("Sales counter #" .. strategy, function()
-  local bp, db
+  local bp
   local mock_service
   local mock, mock_port
   local admin_client, proxy_client
   local healthz_route_id1 = utils.uuid()
   local healthz_route_id2 = utils.uuid()
 
-  lazy_setup(function()
-    mock = assert(http_mock.new(nil, {
-      ["/"] = {
-        content = [[
-          ngx.print("congrats, it's a mock")
-          ngx.flush(true)
-        ]]
-      },
-    }, nil))
-    assert(mock:start())
-    mock_port = tonumber(mock:get_default_port())
-
-    bp, db = helpers.get_db_utils(strategy, {
-      "routes",
-      "services",
-    })
-
-    mock_service = bp.services:insert({
-      host = "localhost",
-      port = mock_port,
-    })
-
-    local mock_upstream = bp.upstreams:insert({
-      name = "mock_upstream",
-    })
-
-    bp.targets:insert({
-      upstream = { id = mock_upstream.id },
-      target = mock_service.host .. ":" .. mock_service.port,
-    })
-
-    bp.routes:insert({
-      name = "a-regular-route",
-      paths = { "/regular" },
-      service = mock_service,
-    })
-
-    bp.routes:insert({
-      name = "another-regular-route",
-      paths = { "/also-regular" },
-      protocols = { "http" },
-      service = mock_service,
-    })
-
-    bp.routes:insert({
-      name = "healthz-route",
-      id = healthz_route_id1,
-      paths = { "/healthz" },
-      protocols = { "http" },
-      service = mock_service,
-    })
-
-    bp.routes:insert({
-      name = "secondary-healthz-route",
-      id = healthz_route_id2,
-      paths = { "/statuz" },
-      protocols = { "http" },
-      service = mock_service,
-    })
-
-    assert(helpers.start_kong({
-      healthz_ids = string.format("%s, %s", healthz_route_id1, healthz_route_id2),
-      database = strategy,
-      license_path = "spec-ee/fixtures/mock_license.json",
-      analytics_flush_interval = 1,
-    }))
-
-  end)
-
-  lazy_teardown(function()
-    helpers.stop_kong()
-  end)
-
   before_each(function()
     admin_client = helpers.admin_client()
     proxy_client = helpers.proxy_client()
@@ -110,6 +37,79 @@ describe("Sales counter #" .. strategy, function()
   end)
 
   describe("request_count", function()
+    lazy_setup(function()
+      mock = assert(http_mock.new(nil, {
+        ["/"] = {
+          content = [[
+            ngx.print("congrats, it's a mock")
+            ngx.flush(true)
+          ]]
+        },
+      }, nil))
+      assert(mock:start())
+      mock_port = tonumber(mock:get_default_port())
+
+      bp = helpers.get_db_utils(strategy, {
+        "routes",
+        "services",
+      })
+
+      mock_service = bp.services:insert({
+        host = "localhost",
+        port = mock_port,
+      })
+
+      local mock_upstream = bp.upstreams:insert({
+        name = "mock_upstream",
+      })
+
+      bp.targets:insert({
+        upstream = { id = mock_upstream.id },
+        target = mock_service.host .. ":" .. mock_service.port,
+      })
+
+      bp.routes:insert({
+        name = "a-regular-route",
+        paths = { "/regular" },
+        service = mock_service,
+      })
+
+      bp.routes:insert({
+        name = "another-regular-route",
+        paths = { "/also-regular" },
+        protocols = { "http" },
+        service = mock_service,
+      })
+
+      bp.routes:insert({
+        name = "healthz-route",
+        id = healthz_route_id1,
+        paths = { "/healthz" },
+        protocols = { "http" },
+        service = mock_service,
+      })
+
+      bp.routes:insert({
+        name = "secondary-healthz-route",
+        id = healthz_route_id2,
+        paths = { "/statuz" },
+        protocols = { "http" },
+        service = mock_service,
+      })
+
+      assert(helpers.start_kong({
+        healthz_ids = string.format("%s, %s", healthz_route_id1, healthz_route_id2),
+        database = strategy,
+        license_path = "spec-ee/fixtures/mock_license.json",
+        analytics_flush_interval = 1,
+      }))
+
+    end)
+
+    lazy_teardown(function()
+      helpers.stop_kong()
+      mock:stop()
+    end)
 
     it("correctly counts requests", function()
       local requests = 10
@@ -191,12 +191,98 @@ describe("Sales counter #" .. strategy, function()
       end)
       .with_timeout(10)
       .is_truthy("failed to count total number of requests")
+    end)
+  end)
+
+  describe("request_count", function()
+    lazy_setup(function()
+      mock = assert(http_mock.new(nil, {
+        ["/"] = {
+          content = [[
+            ngx.print("congrats, it's a mock")
+            ngx.flush(true)
+          ]]
+        },
+      }, nil))
+      assert(mock:start())
+      mock_port = tonumber(mock:get_default_port())
+
+      bp = helpers.get_db_utils(strategy, {
+        "routes",
+        "services",
+      })
+
+      mock_service = bp.services:insert({
+        host = "localhost",
+        port = mock_port,
+      })
+
+      local mock_upstream = bp.upstreams:insert({
+        name = "mock_upstream",
+      })
+
+      bp.targets:insert({
+        upstream = { id = mock_upstream.id },
+        target = mock_service.host .. ":" .. mock_service.port,
+      })
+
+      bp.routes:insert({
+        name = "a-regular-route",
+        paths = { "/regular" },
+        service = mock_service,
+      })
+
+      bp.plugins:insert({
+        name = "pre-function",
+        config = {
+          log = {[[
+            panic()
+          ]]},
+        },
+      })
+
+      assert(helpers.start_kong({
+        database = strategy,
+        license_path = "spec-ee/fixtures/mock_license.json",
+        analytics_flush_interval = 1,
+      }))
 
     end)
 
+    lazy_teardown(function()
+      helpers.stop_kong()
+      mock:stop()
+    end)
+
+    it("correctly counts requests where plugin throws exception in the log phase", function()
+      local requests = 10
+      local res
+
+      res = assert(admin_client:get("/license/report"))
+      local body = assert.res_status(200, res)
+      local json = cjson.decode(body)
+      local original_request_count = tonumber(json.counters.total_requests)
+
+      for i=1,requests do
+        res = proxy_client:send({
+          method = "GET",
+          path = "/regular",
+        })
+        assert.response(res).has_status(200)
+      end
+
+      assert.eventually(function()
+        res = assert(admin_client:get("/license/report"))
+        body = assert.res_status(200, res)
+        json = cjson.decode(body)
+        local total_request_count = tonumber(json.counters.total_requests)
+        return (original_request_count + requests) == total_request_count
+      end)
+      .with_timeout(10)
+      .is_truthy("failed to count total number of requests")
+    end)
   end)
 
 end)
 
 end
-