algod: Add static EnableTelemetry retry

[urtho]

Remote telemetry with a static URI in config never gets enabled past the initial, single try at algod startup.
Remote logging to static URI never gets enabled in the event the Internet or remote service is not available during Algod startup.

There is no such issue with dynamic remote telemetry (DNS based discovery) as it retries the connection with TelemetryURIUpdateService.

This PR adds a loop that retries the static remote service every minute until it succeeds.

[urtho]

This one does not solve the HeartBeat race where HB sometimes is not being sent via telemetry.

[jannotti]

I'm ok with adding the go routine loop, but if we're doing that, let's only do that. We can remove the initial attempt to enable, and only enable in the loop.

[urtho]

This change will make static telemetry init fully async instead of sync.
Initial Start and HeartBeat events will be lost in most startup cases with static URI - same as it is now with DNS telemetry.

[codecov]

Codecov Report

Attention: Patch coverage is 18.18182% with 18 lines in your changes missing coverage. Please review.

Project coverage is 51.78%. Comparing base (5f12e1a) to head (5d93b6b).
Report is 7 commits behind head on master.

Files with missing lines	Patch %	Lines
cmd/algod/main.go	0.00%	10 Missing ⚠️
logging/telemetryhook.go	40.00%	3 Missing ⚠️
logging/log.go	0.00%	2 Missing ⚠️
logging/telemetry.go	50.00%	2 Missing ⚠️
cmd/algoh/main.go	0.00%	1 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #6183      +/-   ##
==========================================
- Coverage   51.80%   51.78%   -0.02%     
==========================================
  Files         644      644              
  Lines       86505    86514       +9     
==========================================
- Hits        44816    44804      -12     
- Misses      38822    38843      +21     
  Partials     2867     2867              

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[gmalouf]

@urtho want to merge in master here and we'll get this pulled in?

[jannotti]

This change will make static telemetry init fully async instead of sync.
Initial Start and HeartBeat events will be lost in most startup cases with static URI - same as it is now with DNS telemetry.

To keep those, how about a short sleep, say 2 seconds, after starting the go routine?

If you want to get very fancy, you could have the init code write to a channel when it completes, and the sleep could be a select on the channel or until a few seconds timer expires. But I would be happy with a short also and a comment explaining the reasoning.

[jannotti]

I would accept this, but I'd prefer a little delay to try to get telemetry initialized before start events.

[algorandskiy]

To keep those, how about a short sleep, say 2 seconds, after starting the go routine?

Maybe just to try a synchronous init attempt and then run a goroutine in case of failure?

[urtho]

@algorandskiy this was in original PR - try sync one time and fallback to async loop on error.

[algorandskiy]

To me an ideal solution would be something like this.

1. Try a first time synchronously
   1. Modify createTelemetryHook (and createElasticHook) to take cancellable context and call elastic.DialContext(ctx, options...) instead of elastic.NewClient
   2. Create that context with timeout (say 5s timeout?) in EnableTelemetry or let its callers to provide one.
2. Run a goroutine trying with a minute delay (as this PR sugggests) or with backoff.

[urtho]

@algorandskiy

ctx in Dial elastic.NewClient already has a set of built-in timeouts but there are cases where cluster interrogation might make the initial process too long. Adding a timeout context is a good precaution.

Testing the patch with timeout context now.

[algorandskiy]

Thank you! Missing ctx usage in createElasticHookContext, other than that looks great!

[algorandskiy]

@urtho could you fix linter error (make DefaultStaticTelemetryStartupTimeout unexported is fine) and my feedback?

[urtho]

@algorandskiy
linter does not like it when I ignore the cancel fn

cmd/algod/main.go:242:9: lostcancel: the cancel function returned by context.WithTimeout should be called, not discarded, to avoid a context leak (govet)
                        ctx, _ := context.WithTimeout(context.Background(), defaultStaticTelemetryStartupTimeout)
                             ^
make: *** [Makefile:115: lint] Error 1

[algorandskiy]

Indeed

Canceling this context releases resources associated with it, so code should call cancel as soon as the operations running in this Context complete.

[urtho]

OK, going to non-deferred cancel like in

go-algorand/ledger/catchpointtracker.go

Lines 1273 to 1279 in 113b0c3

	stepCtx, stepCancelFunction := context.WithTimeout(dbCtx, chunkExecutionDuration)
	writeStepStartTime := time.Now()
	more, err = catchpointWriter.FileWriteStep(stepCtx)
	// accumulate the actual time we've spent writing in this step.
	catchpointGenerationStats.CPUTime += uint64(time.Since(writeStepStartTime).Nanoseconds())
	stepCancelFunction()
	if more && err == nil {

[jannotti]

I thought I was following all the Context plumbing, but when it gets to here I don't understand. It seems like the context is being dropped now, so how can the original context.WithTimeout actually work?

[algorandskiy]

you mean in this test?

in the code the context plumbed down to
createTelemetryHookContext -> hookFactory -> createElasticHookContext -> elastic.DialContext