Fix https_batch deadlock due to golang timer changes #648

nicklas-dohrn · 2024-12-13T13:08:02Z

What is changed:

This changes the way the syslog batches are triggered.
The new implementation no longer uses Timers that need to be reset and checked, it just ticks once every second per http_batch drain to send a batch at least once a second.
The new logic is as follows:

If there is a log present in the queue, send it at last one second later with every log from the same second.
If there are more logs in one second than the 'batchSize' allows, send the batch immediately

The problem fixed by this change:

The old implementation was able to deadlock itself due to the way the time channel was reset. There are even more changes to this behaviour to be expected by the golang 1.23 update. (https://tip.golang.org/doc/go1.23#timer-changes)
-> Changed logic necessary to prevent further issues on further golang upgrades

Impact:

The new implementation will tick more often, but the overhead will be pretty minimal, due to not doing anything for empty drains.

Type of change

Bug fix (non-breaking change which fixes an issue)

Testing performed?

Unit tests
Tested in dev cluster

Checklist:

This PR is being made against the main branch, or relevant version branch
I have made corresponding changes to the documentation
I have added testing for my changes

juergen-walter · 2024-12-16T09:42:44Z

@ctlong can you check please

chombium

@nicklas-dohrn Thanks for the fix. Please take a look at the linting errors. There is no error checking after the sendHttpRequest call.

src/pkg/egress/syslog/https_batch.go

ctlong

Can you write a failing test for the old logic that works for the new logic?

nicklas-dohrn · 2024-12-20T08:23:57Z

I am currently in the process to rewrite the tests anyway, but I will make sure to have a test that proves the point, that the old implementation deadlocks/hangs in certain scenarios.

nicklas-dohrn · 2024-12-29T11:21:58Z

This change now contains a test case, that will not work with the old timer based implementation.
I added a test configurable defaultTime for the ticker, to keep test cases shorter than I would need with 1 second intervalls.

chombium

The code looks good, but we'll have to do some integration tests as well before approving the PR.

chombium

Hi @nicklas-dohrn, thanks for the changes and the fix. It looks good to me and if @ctlong doesn't have any objections we can merge this.

chombium · 2025-01-23T13:59:58Z

src/pkg/egress/syslog/https_batch.go

@@ -13,6 +13,8 @@ import (

 const BATCHSIZE = 256 * 1024

+var DefaultSendInterval = 1 * time.Second


I wonder if we need to expose config parameters which can be set with envvars on Syslog Agent start.

I don't have anything against, that we merge this as is and we open up the config parameters later.

Any thoughts on this @ctlong?

nicklas-dohrn · 2025-01-24T08:29:11Z

Unfortunately, I cannot see the failures due to the concourse build check.
It would be nice to know, what I should fix here.

juergen-walter · 2025-02-13T13:03:15Z

Hi @ameowlia @ctlong not having access nor any information about failing concourse-ci/tests is discouraging and a huge delay factor for open source contributors such as @nicklas-dohrn. Any ideas on how to improve? Next PR is already in the pipeline #617

ctlong · 2025-02-18T01:04:19Z

Hi @ameowlia @ctlong not having access nor any information about failing concourse-ci/tests is discouraging and a huge delay factor for open source contributors such as @nicklas-dohrn. Any ideas on how to improve? Next PR is already in the pipeline #617

Sorry that is blocking progress here. I'm aware that the lack of visibility with these PR tests are not ideal, but there's no quick fixes to expose this pipeline or move it to an open source concourse at the moment.

I'm happy to discuss in Slack the path I'm attempting to take to open source the pipelines. I'll take any help that I can get to implement the plan 😄

ctlong · 2025-02-18T01:12:10Z

Here's the failure:

$ go run github.com/onsi/ginkgo/v2/ginkgo -r --randomize-all --randomize-suites --fail-on-pending --keep-going --race --trace
...
------------------------------
• [FAILED] [0.146 seconds]
HTTPS_batch [It] test dispatching for batches before timewindow is finished
/tmp/build/f541ec31/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:100

  Timeline >>
  2025/02/18 01:05:36 Dropped 10000 dropping logs for app-id's app drain with url dropping:
  2025/02/18 01:05:36 Dropped 10000 dropping logs for app-id's app drain with url dropping:
  2025/02/18 01:05:36 Dropped 10000 dropping logs for app-id's app drain with url dropping:
  2025/02/18 01:05:36 Dropped 10000 dropping logs for app-id's app drain with url dropping:
  [FAILED] in [It] - /tmp/build/f541ec31/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:105 @ 02/18/25 01:05:36.995
  << Timeline

  [FAILED] Expected
      <int>: 257
  to equal
      <int>: 256
  In [It] at: /tmp/build/f541ec31/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:105 @ 02/18/25 01:05:36.995

  Full Stack Trace
    code.cloudfoundry.org/loggregator-agent-release/src/pkg/egress/syslog_test.init.func3.4()
    	/tmp/build/f541ec31/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:105 +0x4fe

Concourse container is an x86_64 Linux OS with 16 cores.

chombium · 2025-02-18T01:44:11Z

I've run the test now few times on my machine with Ubuntu 22.04 and from four runs I've got three errors and one successful run.. It seems to me that as the code plays with time ranges and the randomness that we run the test suite with, makes problems. The tests should be more robust, I guess... @nicklas-dohrn wdyt?

chombium · 2025-02-18T01:45:32Z

I'm happy to discuss in Slack the path I'm attempting to take to open source the pipelines. I'll take any help that I can get to implement the plan 😄

@ctlong I would gladly help you with this ;)

ctlong · 2025-02-18T01:52:28Z

It seems like the "test dispatching for batches before timewindow is finished" test assumes that the following lines can be executed within one second:

env1 := buildLogEnvelope("APP", "1", "string to get log to 1024 characters:"+string_to_1024_chars, loggregator_v2.Log_OUT)
for i := 0; i < 300; i++ {
    Expect(writer.Write(env1)).To(Succeed())
}
Expect(drain.getMessagesSize()).Should(Equal(256))

If they take longer than one second, then more envelopes may be present in the drain than just 256.

Why not make the DefaultSendInterval very large just for this test and remove the sleep and final expectation?

nicklas-dohrn · 2025-02-18T14:16:42Z

I took your inspiration for the testcase:
"test dispatching for batches before timewindow is finished"

but did it kind of the other way around:
if reducing the overall size of the batch, the timings should be less tight, so the fast execution time should work.
I also changed the bigger sized logs to not hit the buffer size limit directly, to account for inconsistencies in object to string materialisation (not sure if this can happen, but now it is also really clear, when the buffer limit is breached)

I hope that with the other changes I introduced will make this completely consistently succeed

chombium · 2025-02-18T20:09:28Z

This looks good. I'll do few more unit test runs tomorrow, so that we are sure that the problem is fixed.

chombium

Hi @nicklas-dohrn, thank you very much for the quick reponse.

I have few more small objections and than I will test the changes once again. Could you please also squash your commits?

chombium · 2025-02-20T09:33:51Z

src/pkg/egress/syslog/https_batch.go

@@ -11,7 +11,8 @@ import (
 	"code.cloudfoundry.org/loggregator-agent-release/src/pkg/egress"
 )

-const BATCHSIZE = 256 * 1024
+var DefaultBatchSize = 256 * 1024


Could you please make these two as constants?

They cannot be constants, as they need to be set in the Tests.
There seems to be no easy way around doing it like this, so can we not keep it this way?

For cases like this we're using the so called Functional options pattern. An object is created with default values and then options are applied.Sorry for not mentioning it earlier...
Here is an example definition and [usage](https://github.com/cloudfoundry/loggregator-agent-release/blob/main/src/cmd/loggregator-agent/app/app_v2.go#L173] from this project.

You can find more info about this pattern in the following blog posts:
https://dev.to/kittipat1413/understanding-the-options-pattern-in-go-390c
https://golang.cafe/blog/golang-functional-options-pattern.html

This way, you will be able to have the default values configured and can be overwritten if needed.

src/pkg/egress/syslog/https_batch_test.go

nicklas-dohrn · 2025-02-24T08:17:50Z

@ctlong if this one runs through, you can merge it now.
should be stable now.

chombium

Hi @nicklas-dohrn, I have a suggestion how to restructure the code for setting he default values and I was able to make the test break again.

I've run the Ginkgo test 10 times one after another:

 for i in {1..10}; do go run github.com/onsi/ginkgo/v2/ginkgo -r --randomize-all --randomize-suites --fail-on-pending --keep-going --race --trace >> /tmp/nicklas.log; done

The broken tests are:

[1740406427] Syslog Suite - 84/84 specs ••••••••••••
------------------------------
• [FAILED] [0.165 seconds]
HTTPS_batch [It] testing simple appending of one log
/tmp/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:62

  Timeline >>
  2025/02/24 15:13:56 Dropped 10000 dropping logs for aggregate drain with url dropping:
  2025/02/24 15:13:56 Dropped 10000 dropping logs for test-source-id's app drain with url dropping://my-drain:8080/path
  [FAILED] in [It] - /tmp/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:69 @ 02/24/25 15:13:56.394
  << Timeline

  [FAILED] Expected
      <int>: 0
  to equal
      <int>: 2
  In [It] at: /tmp/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:69 @ 02/24/25 15:13:56.394

  Full Stack Trace
    code.cloudfoundry.org/loggregator-agent-release/src/pkg/egress/syslog_test.init.func3.2()
    	/tmp/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:69 +0x87e
------------------------------
••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••
------------------------------
• [FAILED] [0.193 seconds]
HTTPS_batch [It] test batch dispatching with all logs in a given timeframe
/tmp/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:96

  Timeline >>
  2025/02/24 15:13:59 Dropped 10000 dropping logs for aggregate drain with url dropping:
  2025/02/24 15:13:59 Dropped 10000 dropping logs for test-source-id's app drain with url dropping://my-drain:8080/path
  2025/02/24 15:13:59 Dropped 10000 dropping logs for app-id's app drain with url dropping:
  2025/02/24 15:13:59 Dropped 10000 dropping logs for aggregate drain with url dropping:
  2025/02/24 15:13:59 Dropped 10000 dropping logs for test-source-id's app drain with url dropping://my-drain:8080/path
  2025/02/24 15:13:59 Dropped 10000 dropping logs for app-id's app drain with url dropping:
  [FAILED] in [It] - /tmp/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:102 @ 02/24/25 15:13:59.6
  << Timeline

  [FAILED] Timed out after 0.189s.
  Expected
      <int>: 0
  to equal
      <int>: 10
  In [It] at: /tmp/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:102 @ 02/24/25 15:13:59.6

  Full Stack Trace
    code.cloudfoundry.org/loggregator-agent-release/src/pkg/egress/syslog_test.init.func3.3()
    	/tmp/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:102 +0x668
------------------------------
••••

Summarizing 2 Failures:
  [FAIL] HTTPS_batch [It] testing simple appending of one log
  /tmp/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:69
  [FAIL] HTTPS_batch [It] test batch dispatching with all logs in a given timeframe
  /tmp/loggregator-agent-release/src/pkg/egress/syslog/https_batch_test.go:102

Ran 84 of 84 Specs in 3.763 seconds
FAIL! -- 82 Passed | 2 Failed | 0 Pending | 0 Skipped

These two tests fail randomly.

Please squash your commits as well.

chombium · 2025-02-24T14:09:32Z

src/pkg/egress/syslog/https_batch.go

@@ -11,7 +11,8 @@ import (
 	"code.cloudfoundry.org/loggregator-agent-release/src/pkg/egress"
 )

-const BATCHSIZE = 256 * 1024
+var DefaultBatchSize = 256 * 1024


For cases like this we're using the so called Functional options pattern. An object is created with default values and then options are applied.Sorry for not mentioning it earlier...
Here is an example definition and [usage](https://github.com/cloudfoundry/loggregator-agent-release/blob/main/src/cmd/loggregator-agent/app/app_v2.go#L173] from this project.

You can find more info about this pattern in the following blog posts:
https://dev.to/kittipat1413/understanding-the-options-pattern-in-go-390c
https://golang.cafe/blog/golang-functional-options-pattern.html

This way, you will be able to have the default values configured and can be overwritten if needed.

It makes tests hopefully more robust It also replaces most sleeps with Consistently and Eventually. It makes the timings more forgiving. This should make it reliable on weak hardware. Add functional options pattern to allow test configuration

chombium

LGTM! @nicklas-dohrn thanks for your contribution and the cooperation.

nicklas-dohrn requested a review from a team as a code owner December 13, 2024 13:08

nicklas-dohrn force-pushed the main branch 3 times, most recently from 5e8242f to b73bec2 Compare December 13, 2024 13:27

chombium requested changes Dec 16, 2024

View reviewed changes

src/pkg/egress/syslog/https_batch.go Outdated Show resolved Hide resolved

nicklas-dohrn requested a review from chombium December 17, 2024 17:43

ctlong reviewed Dec 19, 2024

View reviewed changes

nicklas-dohrn force-pushed the main branch 2 times, most recently from 6a6a850 to f0d7e6c Compare December 29, 2024 11:19

nicklas-dohrn requested a review from ctlong December 29, 2024 11:20

nicklas-dohrn force-pushed the main branch from f0d7e6c to fb5fe34 Compare December 29, 2024 11:23

ctlong self-assigned this Jan 10, 2025

chombium reviewed Jan 17, 2025

View reviewed changes

nicklas-dohrn requested a review from chombium January 23, 2025 10:29

chombium previously approved these changes Jan 23, 2025

View reviewed changes

ctlong previously approved these changes Feb 18, 2025

View reviewed changes

nicklas-dohrn dismissed stale reviews from ctlong and chombium via 8fdf4e8 February 18, 2025 14:10

nicklas-dohrn force-pushed the main branch from 8fdf4e8 to 4966266 Compare February 18, 2025 14:12

nicklas-dohrn requested review from chombium and ctlong February 18, 2025 14:59

nicklas-dohrn force-pushed the main branch from 82dc11c to 366f9f1 Compare February 20, 2025 09:28

chombium requested changes Feb 20, 2025

View reviewed changes

nicklas-dohrn requested a review from chombium February 20, 2025 15:30

ctlong assigned chombium and unassigned ctlong Feb 20, 2025

chombium requested changes Feb 24, 2025

View reviewed changes

nicklas-dohrn force-pushed the main branch 3 times, most recently from e7e9fba to 5d67c23 Compare February 26, 2025 17:01

nicklas-dohrn requested a review from chombium February 27, 2025 07:43

nicklas-dohrn force-pushed the main branch from 5d67c23 to 7a5fab6 Compare February 27, 2025 12:52

chombium approved these changes Mar 5, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix https_batch deadlock due to golang timer changes #648

Fix https_batch deadlock due to golang timer changes #648

nicklas-dohrn commented Dec 13, 2024 •

edited

Loading

juergen-walter commented Dec 16, 2024

chombium left a comment

ctlong left a comment

nicklas-dohrn commented Dec 20, 2024

nicklas-dohrn commented Dec 29, 2024

chombium left a comment

chombium left a comment

chombium Jan 23, 2025

nicklas-dohrn commented Jan 24, 2025

juergen-walter commented Feb 13, 2025

ctlong commented Feb 18, 2025

ctlong commented Feb 18, 2025

chombium commented Feb 18, 2025

chombium commented Feb 18, 2025 •

edited

Loading

ctlong commented Feb 18, 2025 •

edited

Loading

nicklas-dohrn commented Feb 18, 2025 •

edited

Loading

chombium commented Feb 18, 2025

chombium left a comment

chombium Feb 20, 2025

nicklas-dohrn Feb 20, 2025

chombium Feb 24, 2025

nicklas-dohrn commented Feb 24, 2025

chombium left a comment

chombium Feb 24, 2025

chombium left a comment

		@@ -13,6 +13,8 @@ import (

		const BATCHSIZE = 256 * 1024

		var DefaultSendInterval = 1 * time.Second

Fix https_batch deadlock due to golang timer changes #648

Are you sure you want to change the base?

Fix https_batch deadlock due to golang timer changes #648

Conversation

nicklas-dohrn commented Dec 13, 2024 • edited Loading

What is changed:

The problem fixed by this change:

Impact:

Type of change

Testing performed?

Checklist:

juergen-walter commented Dec 16, 2024

chombium left a comment

Choose a reason for hiding this comment

ctlong left a comment

Choose a reason for hiding this comment

nicklas-dohrn commented Dec 20, 2024

nicklas-dohrn commented Dec 29, 2024

chombium left a comment

Choose a reason for hiding this comment

chombium left a comment

Choose a reason for hiding this comment

chombium Jan 23, 2025

Choose a reason for hiding this comment

nicklas-dohrn commented Jan 24, 2025

juergen-walter commented Feb 13, 2025

ctlong commented Feb 18, 2025

ctlong commented Feb 18, 2025

chombium commented Feb 18, 2025

chombium commented Feb 18, 2025 • edited Loading

ctlong commented Feb 18, 2025 • edited Loading

nicklas-dohrn commented Feb 18, 2025 • edited Loading

chombium commented Feb 18, 2025

chombium left a comment

Choose a reason for hiding this comment

chombium Feb 20, 2025

Choose a reason for hiding this comment

nicklas-dohrn Feb 20, 2025

Choose a reason for hiding this comment

chombium Feb 24, 2025

Choose a reason for hiding this comment

nicklas-dohrn commented Feb 24, 2025

chombium left a comment

Choose a reason for hiding this comment

chombium Feb 24, 2025

Choose a reason for hiding this comment

chombium left a comment

Choose a reason for hiding this comment

nicklas-dohrn commented Dec 13, 2024 •

edited

Loading

chombium commented Feb 18, 2025 •

edited

Loading

ctlong commented Feb 18, 2025 •

edited

Loading

nicklas-dohrn commented Feb 18, 2025 •

edited

Loading