Skip to content

testing: fix unit test TestAsyncTelemetryHook_QueueDepth #2685

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.

Sign up for GitHub

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

Merged
tsachiherman merged 2 commits into from
Jan 7, 2022
Merged

testing: fix unit test TestAsyncTelemetryHook_QueueDepth #2685

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
ad94331
Fix unit test.
tsachiherman Aug 4, 2021
3a1085f
Merge branch 'master' into tsachi/fixqueuedepthtest
tsachiherman Sep 20, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 6 additions & 1 deletion logging/telemetryhook_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -225,5 +225,10 @@ func TestAsyncTelemetryHook_QueueDepth(t *testing.T) {
close(filling)
hook.Close()

require.Equal(t, maxDepth, len(testHook.entries()))
hookEntries := len(testHook.entries())
require.GreaterOrEqual(t, hookEntries, maxDepth)
// the anonymous goroutine in createAsyncHookLevels might pull an entry off the pending list before
// writing it off to the underlying hook. when that happens, the total number of sent entries could
// be one higher then the maxDepth.
require.LessOrEqual(t, hookEntries, maxDepth+1)
Copy link
Copy Markdown
Contributor

@winder winder Aug 4, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think that moving hook.ready = true after the Fire calls would remove the race condition. After close(filling) would work too but I don't think it's required.

Actually, the filling channel doesn't seem to be needed at all.

This logging code is pretty hard to follow, but I think this is the main loop:

		for !exit {
			exit = !hook.waitForEventAndReady()

			hasEvents := true
			for hasEvents {
				select {
				case entry := <-hook.entries:
					hook.appendEntry(entry)
				default:
					hook.Lock()
					var entry *logrus.Entry
---->					if len(hook.pending) > 0 && hook.ready { // entry is always nil when ready = false
						entry = hook.pending[0]
						hook.pending = hook.pending[1:]
					}
					hook.Unlock()
					if entry != nil {
---->						err := hook.wrappedHook.Fire(entry) // therefore the mock will not be triggered
						if err != nil {
							Base().Warnf("Unable to write event %#v to telemetry : %v", entry, err)
						}
						hook.wg.Done()
					} else {
						hasEvents = false
					}
				}
			}

Copy link
Copy Markdown
Contributor Author

@tsachiherman tsachiherman Aug 4, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree that the code is a bit spaghetti like; but I don't believe that changing hook.ready would help:
The variable is not being blocked upon. waitForEventAndReady doesn't wait for the ready flag, but rather just return the ready flag state.

The filling variable helps to ensure we block the err := hook.wrappedHook.Fire(entry) call, so that we can fill up the hook.entries channel. Then, once the channel is full, we unblock the Fire call.

Copy link
Copy Markdown
Contributor Author

@tsachiherman tsachiherman Aug 4, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sorry - I misread your response. I believe that depending on the scenario we want to execute, there are more than one way to fix the test. My plan was to change the expectation, as the test current doing the following:

  1. write the first entry to the hook.
  2. the Fire is writing to the entries; entries is read and calling the inner Fire. The inner Fire is being block.
  3. the rest of the entries are being written, leaving 10 entries in the pending array.
  4. The inner Fire is getting unblocked.
  5. The anonymous method finish iterating over the remaining entries.

The total number of entries is either 10 or 11, depending on whether the #2 was executed before all the entries were written.

Copy link
Copy Markdown
Contributor

@winder winder Aug 4, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The test name is TestAsyncTelemetryHook_QueueDepth, so I believe moving the ready location forces the surplus events to be discarded according to the QueueDepth. So it seems like the right way to go.

TestAsyncTelemetryHook_CloseDrop also uses the ready flag, I don't think it tests "CloseDrop" at all.

The complexity of this code is pretty absurd, maybe we can revive the "Externalized Telemetry" project and replace it entirely with a better design.

}