testing: fix unit test TestAsyncTelemetryHook_QueueDepth

[tsachiherman]

Summary

Fix the unit test TestAsyncTelemetryHook_QueueDepth:

	// 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.

Test Plan

This is a test.

[winder]

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
					}
				}
			}

[tsachiherman]

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.

[tsachiherman]

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.

[winder]

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.

[codecov-commenter]

Codecov Report

Merging #2685 (3a1085f) into master (dbab85f) will increase coverage by 0.01%.
The diff coverage is n/a.

@@            Coverage Diff             @@
##           master    #2685      +/-   ##
==========================================
+ Coverage   47.29%   47.30%   +0.01%     
==========================================
  Files         356      356              
  Lines       57240    57240              
==========================================
+ Hits        27071    27078       +7     
+ Misses      27103    27100       -3     
+ Partials     3066     3062       -4     

Impacted Files	Coverage Δ
cmd/algoh/blockWatcher.go	77.77% <0.00%> (-3.18%)	⬇️
ledger/blockqueue.go	82.18% <0.00%> (-2.88%)	⬇️
catchup/service.go	68.57% <0.00%> (-1.56%)	⬇️
network/wsNetwork.go	60.90% <0.00%> (-0.19%)	⬇️
data/transactions/verify/txn.go	44.29% <0.00%> (ø)
cmd/tealdbg/debugger.go	73.86% <0.00%> (+1.00%)	⬆️
crypto/merkletrie/node.go	93.48% <0.00%> (+1.86%)	⬆️
agreement/proposalManager.go	98.03% <0.00%> (+1.96%)	⬆️
crypto/merkletrie/trie.go	68.61% <0.00%> (+2.18%)	⬆️
agreement/cryptoVerifier.go	77.94% <0.00%> (+2.20%)	⬆️
... and 1 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update dbab85f...3a1085f. Read the comment docs.

[winder]

Stephen found a data race related to modifying the telemetry hook while entries were queued. Since there are plans to redo telemetry at some point, I don't think we should spend time investigating that race.

[tsachiherman]

We shouldn't have any data races.. but I don't mind holding off with fixing the data race if it doesn't happen on production.