fix(plugins/http-log): improve concurrency when max_batch_size is set to 1 #13332

vm-001 · 2024-07-04T05:39:45Z

Summary

Checklist

The Pull Request has tests
A changelog file has been created under changelog/unreleased/kong or skip-changelog label added on PR if changelog is unnecessary. README.md
There is a user-facing docs PR against https://github.com/Kong/docs.konghq.com - PUT DOCS PR HERE

Issue reference

FTI-6022

… to 1

hanshuebner · 2024-07-04T06:07:34Z

kong/plugins/http-log/handler.lua

+
+        if (ngx.now() - start_time) > queue_conf.max_retry_time then
+          kong.log.err(string.format(
+            "could not send entries, giving up after %d retries. 1 queue entries were lost",


As the maximum retry time is configured, it should probably be reported instead of in addition to the number of retries so that it is clear what knob to turn in case this message ist shown.

Does changing log like this make sense to you?

kong.log.err(string.format( "could not send entries, giving up after %d retries. 1 queue entries were lost。 Please consider tune the configuration max_retry_time", retry_count)) break

I update the log message to indicate the max_retry_time is exceeded

kong/plugins/http-log/handler.lua

changelog/unreleased/kong/http-log-Improvement.yml

Co-authored-by: Hans Hübner <hans.huebner@gmail.com>

hanshuebner · 2024-07-04T07:08:04Z

I think the new behavior should be enabled by an explicit configuration parameter (no_queue) rather than implicit by a certain queue length. This would make it easier to understand.

spec/03-plugins/03-http-log/01-log_spec.lua

spec/01-unit/27-queue_spec.lua

kong/plugins/http-log/handler.lua

spec/03-plugins/03-http-log/01-log_spec.lua

Co-authored-by: Hans Hübner <hans.huebner@gmail.com>

outsinre · 2024-07-12T07:12:29Z

changelog/unreleased/kong/http-log-concurrent-optimize.yml

@@ -0,0 +1,4 @@
+message: |
+  **HTTP-Log**: When `queue.max_batch_size` is 1, log entries are now sent in separate, parallel HTTP requests.  Previously, they were sent sequentially in FIFO order.


Suggested change

**HTTP-Log**: When `queue.max_batch_size` is 1, log entries are now sent in separate, parallel HTTP requests. Previously, they were sent sequentially in FIFO order.

**HTTP-Log**: When `queue.max_batch_size` is explicitly set to `1`, log entries are now sent via concurrent HTTP requests. Previously, they were sent sequentially in FIFO order.

The default value of max_batch_size is 1. So words explicitly set is not applicable at this case.

outsinre · 2024-07-12T07:24:01Z

kong/plugins/http-log/handler.lua

+        end
+
+        if (now() - start_time) > queue_conf.max_retry_time then
+          kong.log.err("could not send entries due to max_retry_time exceeded. 1 queue entry was lost")


Suggested change

kong.log.err("could not send entries due to max_retry_time exceeded. 1 queue entry was lost")

kong.log.err("could not send this log entry due to max_retry_time exceeded: lost")

We now reuse the Queue.handle logic, so the suggestion here is not applicable.

outsinre · 2024-07-12T07:28:01Z

kong/plugins/http-log/handler.lua

+  local entry = cjson.encode(kong.log.serialize())
+
+  if queue_conf.max_batch_size == 1 then
+    local ok ,err = timer_at(0, function()


If the TPS is very high, the number of timers would soar. Would that be a problem?

I suppose all the timers would be managed by timer-ng since 3.0. In that case, there will be warning logs from the timer-ng.

kong/plugins/http-log/handler.lua

samugi · 2024-07-16T08:00:34Z

kong/plugins/http-log/handler.lua

+  local entry = cjson.encode(kong.log.serialize())
+
+  if queue_conf.max_batch_size == 1 then
+    local ok ,err = timer_at(0, function()


could we extract the timer's logic in a local function? Also - this looks very similar to the process_once method of the queue. Perhaps we could expose that logic from there and reuse it, to reduce duplication.

I like the idea of function reuse. So the Queue has to expose a function(e.g. Queue:handle) to be used internally and externally.

Here is the function reuse approach PR #13384. However, we have to refactor the Queue a little to expose

Queue.create(): create a Queue instance without starting a background timer, this helps us to leverage the OOP of the queue. (most of the queue's functions are OOP, such as queue:log(), it's hard to reuse these without create a Queue instance : (

Queue:handle(): a function contains retry logic

@samugi @hanshuebner Let me know your thoughts. The function reuse approach has a bit wider code change and is a bit more risky, hence requires more time to do a thoughtful review.

I left a review comment, I hope my observation above didn't cost you too much time and efforts 😸

… to 1

samugi · 2024-07-18T12:59:47Z

kong/plugins/http-log/handler.lua

@@ -189,12 +190,27 @@ function HttpLogHandler:log(conf)

  local queue_conf = Queue.get_plugin_params("http-log", conf, make_queue_name(conf))
  kong.log.debug("Queue name automatically configured based on configuration parameters to: ", queue_conf.name)
+  local entry = cjson.encode(kong.log.serialize())
+
+  if queue_conf.max_batch_size == 1 then


I agree with this comment by Hans:

I think the new behavior should be enabled by an explicit configuration parameter (no_queue) rather than implicit by a certain queue length. This would make it easier to understand.

I don't have a strong opinion about it. Move to internal discussion and the potential backport.

samugi · 2024-07-18T14:14:34Z

kong/plugins/http-log/handler.lua

+      if premature then
+        return
+      end
+      queue:handle({ entry })


the problem with this approach is that we'd be using the Queue to process entries in parallel, i.e. not what a queue normally does. To properly reuse the code (now in the queue) that processes an entry we should probably extract it from the Queue module and then refer to it both from the queue and from here.

If this is too complex for the scope of this task we might want to do it as a separate refactor.

I agree that we extract the retry logic ourside of Queue in another PR.

fix(plugins/http-log): improve concurrency when max_batch_size is set…

9741cfc

… to 1

pull-request-size bot added the size/M label Jul 4, 2024

vm-001 requested a review from hanshuebner July 4, 2024 05:39

github-actions bot added plugins/http-log cherry-pick kong-ee schedule this PR for cherry-picking to kong/kong-ee labels Jul 4, 2024

github-actions bot assigned vm-001 Jul 4, 2024

vm-001 marked this pull request as draft July 4, 2024 05:40

add changelog

d1a2bad

hanshuebner suggested changes Jul 4, 2024

View reviewed changes

vm-001 and others added 3 commits July 4, 2024 14:50

add test case

c777504

update

8b2eb91

Update changelog/unreleased/kong/http-log-Improvement.yml

7f1e1d2

Co-authored-by: Hans Hübner <hans.huebner@gmail.com>

vm-001 marked this pull request as ready for review July 4, 2024 07:30

vm-001 added 2 commits July 4, 2024 15:31

modify changelog file name

8227d31

update log message

786514d

vm-001 requested a review from hanshuebner July 4, 2024 08:18

vm-001 commented Jul 4, 2024

View reviewed changes

spec/03-plugins/03-http-log/01-log_spec.lua Show resolved Hide resolved

vm-001 added 2 commits July 4, 2024 17:25

update test case

2db8db9

why do we need to change this to 7 to make ti test passed?

9ec05b7

vm-001 commented Jul 4, 2024

View reviewed changes

spec/01-unit/27-queue_spec.lua Outdated Show resolved Hide resolved

vm-001 added 2 commits July 4, 2024 18:14

code style: localize

5f37e25

fix test case

fde79e6

hanshuebner reviewed Jul 5, 2024

View reviewed changes

kong/plugins/http-log/handler.lua Outdated Show resolved Hide resolved

spec/03-plugins/03-http-log/01-log_spec.lua Outdated Show resolved Hide resolved

spec/03-plugins/03-http-log/01-log_spec.lua Outdated Show resolved Hide resolved

vm-001 and others added 3 commits July 5, 2024 14:31

Update spec/03-plugins/03-http-log/01-log_spec.lua

731eeae

Co-authored-by: Hans Hübner <hans.huebner@gmail.com>

Update spec/03-plugins/03-http-log/01-log_spec.lua

7fcf583

Co-authored-by: Hans Hübner <hans.huebner@gmail.com>

update message

152761e

outsinre reviewed Jul 12, 2024

View reviewed changes

kong/plugins/http-log/handler.lua Show resolved Hide resolved

samugi reviewed Jul 16, 2024

View reviewed changes

fix(plugins/http-log): improve concurrency when max_batch_size is set…

c160d56

… to 1

pull-request-size bot added size/L and removed size/M labels Jul 17, 2024

samugi reviewed Jul 18, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix(plugins/http-log): improve concurrency when max_batch_size is set to 1 #13332

fix(plugins/http-log): improve concurrency when max_batch_size is set to 1 #13332

vm-001 commented Jul 4, 2024 •

edited

Loading

hanshuebner Jul 4, 2024

vm-001 Jul 4, 2024 •

edited

Loading

vm-001 Jul 4, 2024

hanshuebner commented Jul 4, 2024

outsinre Jul 12, 2024

vm-001 Jul 24, 2024

outsinre Jul 12, 2024

vm-001 Jul 24, 2024

outsinre Jul 12, 2024 •

edited

Loading

vm-001 Jul 24, 2024

samugi Jul 16, 2024

vm-001 Jul 17, 2024 •

edited

Loading

samugi Jul 18, 2024

samugi Jul 18, 2024

vm-001 Jul 24, 2024

samugi Jul 18, 2024

vm-001 Jul 25, 2024

		@@ -0,0 +1,4 @@
		message: \|
		HTTP-Log: When `queue.max_batch_size` is 1, log entries are now sent in separate, parallel HTTP requests. Previously, they were sent sequentially in FIFO order.

	kong.log.err("could not send entries due to max_retry_time exceeded. 1 queue entry was lost")
	kong.log.err("could not send this log entry due to max_retry_time exceeded: lost")

fix(plugins/http-log): improve concurrency when max_batch_size is set to 1 #13332

Are you sure you want to change the base?

fix(plugins/http-log): improve concurrency when max_batch_size is set to 1 #13332

Conversation

vm-001 commented Jul 4, 2024 • edited Loading

Summary

Checklist

Issue reference

Choose a reason for hiding this comment

vm-001 Jul 4, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hanshuebner commented Jul 4, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

outsinre Jul 12, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vm-001 Jul 17, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vm-001 commented Jul 4, 2024 •

edited

Loading

vm-001 Jul 4, 2024 •

edited

Loading

outsinre Jul 12, 2024 •

edited

Loading

vm-001 Jul 17, 2024 •

edited

Loading