Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

DSET-4359: Fix flaky tests #46

Merged
merged 9 commits into from
Jul 31, 2023
Merged

Conversation

martin-majlis-s1
Copy link
Collaborator

@martin-majlis-s1 martin-majlis-s1 commented Jul 27, 2023

When we have introduced RetryShutdownTimeout in the PR #44, we have introduced a bug where if the value is set to 0, then it retries indefinitely - https://pkg.go.dev/github.com/cenkalti/backoff/v4#ExponentialBackOff.

The test add_events_long_running_test.go was flaky, because its as called shutdown immediately after all the events has been submitted asynchronously. There was not enough time to process them and therefore they have been failing.

This PR is also increasing version to 0.12.0

@martin-majlis-s1
Copy link
Collaborator Author

https://github.com/scalyr/dataset-go/actions/runs/5692888480/job/15430824219?pr=46#step:10:297

2023-07-28T14:13:28.540Z	INFO	client/client.go:109	Using config: 	{"config": "Endpoint: http://127.0.0.1:35011/, Tokens: (WriteLog: true, ReadLog: false, WriteConfig: false, ReadConfig: false), BufferSettings: (MaxLifetime: 1s, MaxSize: 1000, GroupBy: [], RetryRandomizationFactor: 1.000000, RetryMultiplier: 1.000000, RetryInitialInterval: 1s, RetryMaxInterval: 1s, RetryMaxElapsedTime: 10s, RetryShutdownTimeout: 30s), ServerHostSettings: (UseHostName: true, ServerHost: )", "version": "0.0.11", "releaseDate": "2023-07-26"}

It should have 30s for shutdown

2023-07-28T14:13:36.698Z	INFO	client/add_events.go:219	Shutting down - BEGIN
2023-07-28T14:13:36.699Z	INFO	client/client.go:425	Buffers' Queue Stats:	{"processed": 2, "enqueued": 5, "dropped": 0, "waiting": 3, "processingS": 5.84072921}
2023-07-28T14:13:36.699Z	INFO	client/client.go:437	Events' Queue Stats:	{"processed": 16723, "enqueued": 16725, "waiting": 2, "processingS": 5.84072921}
2023-07-28T14:13:36.699Z	INFO	client/client.go:451	Transfer Stats:	{"bytesSentMB": 8.695159912109375, "bytesAcceptedMB": 8.695159912109375, "throughputMBpS": 1.4887113576883964, "perBufferMB": 4.3475799560546875, "successRate": 1, "processingS": 5.84072921, "processing": "5.84072921s"}
...
2023-07-28T14:13:40.957Z	INFO	client/client.go:425	Buffers' Queue Stats:	{"processed": 5, "enqueued": 8, "dropped": 0, "waiting": 3, "processingS": 10.978639795}
2023-07-28T14:13:40.957Z	INFO	client/client.go:437	Events' Queue Stats:	{"processed": 29145, "enqueued": 29147, "waiting": 2, "processingS": 10.978639795}
2023-07-28T14:13:40.957Z	INFO	client/client.go:451	Transfer Stats:	{"bytesSentMB": 18.78152847290039, "bytesAcceptedMB": 18.78152847290039, "throughputMBpS": 1.710733644932413, "perBufferMB": 3.756305694580078, "successRate": 1, "processingS": 10.978639795, "processing": "10.978639795s"}
2023-07-28T14:13:40.957Z	INFO	client/add_events.go:247	Shutting down - processing events	{"retryNum": 4, "backoffDelay": "-1ns", "eventsEnqueued": 29147, "eventsProcessed": 29145}
2023-07-28T14:13:40.957Z	INFO	client/add_events.go:262	Shutting down - publishing all buffers
2023-07-28T14:13:40.957Z	INFO	client/add_events.go:455	Publish all buffers	{"numBuffers": 1}
...
We have spent 4s trying to publish all events. But 2 events are somewhere stuck.
...
2023-07-28T14:13:47.298Z	INFO	client/add_events.go:286	Shutting down - processing buffers	{"retryNum": 4, "backoffDelay": "-1ns", "buffersEnqueued": 12, "buffersProcessed": 10, "buffersDropped": 0}
2023-07-28T14:13:47.298Z	ERROR	client/add_events.go:319	Shutting down - not all buffers have been processed	{"retryNum": 4, "buffersEnqueued": 12, "buffersProcessed": 10, "buffersDropped": 0}
github.com/scalyr/dataset-go/pkg/client.(*DataSetClient).Shutdown
	/home/runner/work/dataset-go/dataset-go/pkg/client/add_events.go:319
github.com/scalyr/dataset-go/pkg/client.TestAddEventsManyLogsShouldSucceed
	/home/runner/work/dataset-go/dataset-go/pkg/client/add_events_long_running_test.go:150
testing.tRunner
	/opt/hostedtoolcache/go/1.19.11/x64/src/testing/testing.go:1446
2023-07-28T14:13:47.309Z	INFO	client/client.go:425	Buffers' Queue Stats:	{"processed": 10, "enqueued": 12, "dropped": 0, "waiting": 2, "processingS": 18.122705873}
2023-07-28T14:13:47.309Z	INFO	client/client.go:437	Events' Queue Stats:	{"processed": 45050, "enqueued": 45050, "waiting": 0, "processingS": 18.122705873}
2023-07-28T14:13:47.309Z	INFO	client/client.go:451	Transfer Stats:	{"bytesSentMB": 37.86358642578125, "bytesAcceptedMB": 37.86358642578125, "throughputMBpS": 2.089289904671028, "perBufferMB": 3.786358642578125, "successRate": 1, "processingS": 18.122705873, "processing": "18.122705873s"}
2023-07-28T14:13:47.309Z	ERROR	client/add_events.go:346	Shutting down - error	{"error": "not all buffers have been processed - 2"}
...
We have spent additional 6s in trying to submit buffers.

...
github.com/scalyr/dataset-go/pkg/client.(*DataSetClient).Shutdown
	/home/runner/work/dataset-go/dataset-go/pkg/client/add_events.go:346
github.com/scalyr/dataset-go/pkg/client.TestAddEventsManyLogsShouldSucceed
	/home/runner/work/dataset-go/dataset-go/pkg/client/add_events_long_running_test.go:150
testing.tRunner
	/opt/hostedtoolcache/go/1.19.11/x64/src/testing/testing.go:1446
    add_events_long_running_test.go:151: 
        	Error Trace:	/home/runner/work/dataset-go/dataset-go/pkg/client/add_events_long_running_test.go:151
        	Error:      	Expected nil, but got: &errors.errorString{s:"not all buffers have been processed - 2"}
        	Test:       	TestAddEventsManyLogsShouldSucceed
        	Messages:   	not all buffers have been processed - 2

@codecov-commenter
Copy link

codecov-commenter commented Jul 31, 2023

Codecov Report

Merging #46 (bcbeec3) into main (aca8af3) will increase coverage by 0.60%.
The diff coverage is 74.67%.

Impacted file tree graph

@@            Coverage Diff             @@
##             main      #46      +/-   ##
==========================================
+ Coverage   75.36%   75.95%   +0.60%     
==========================================
  Files          11       11              
  Lines        1534     1572      +38     
==========================================
+ Hits         1156     1194      +38     
+ Misses        315      314       -1     
- Partials       63       64       +1     
Files Changed Coverage Δ
pkg/buffer_config/buffer_config.go 51.85% <20.00%> (+1.46%) ⬆️
pkg/client/add_events.go 86.18% <83.08%> (+1.81%) ⬆️

@martin-majlis-s1 martin-majlis-s1 added this pull request to the merge queue Jul 31, 2023
Merged via the queue into main with commit 9c8ae03 Jul 31, 2023
3 checks passed
@martin-majlis-s1 martin-majlis-s1 deleted the DSET-4359-fix-flaky-tests branch July 31, 2023 11:26
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants