Collect driver stats when driver plugins are restarted

[notnoop]

Fixes #5936 .

This fixes two issues in handling stats in the case where a driver plugin is restarted.

• a bug where we don't properly detect that driver plugin was shutdown during a TaskStats call; so we don't retry properly.
• a bug in StatsHook where retry logic doesn't retry calling Stats! So it loops and then wait until context is done.

Interestingly, there are two retry layers for driver handler calls. Once in LazyHandle that special cases plugin shutdown and once again in the hook. Due to the bugs above, both layers fail to recover. The LazyHandle logic is here:

nomad/client/allocrunner/taskrunner/lazy_handle.go

Lines 141 to 149 in 8da0b91

	out, err := h.Stats(ctx, interval)
	if err == bstructs.ErrPluginShutdown && first {
	first = false
	h, err = l.refreshHandle()
	if err == nil {
	goto TRY
	}
	}

I considered, but decided against, making more substantial refactoring in LazyHandle. LazyHandle tracks its own handlers with its own locking. We can probably simplify the logic to always call tr.getDriverHandle, which is a simple synchornized field lookup - the refresh logic is probably unnecessary. I punted on that for another PR as I want to keep this PR less risky.

[notnoop]

In my rewrite, I flipped this conditional logic. The comment doesn't match the conditional. I assume the comment intends to say that if the plugin is shutdown, we want to log in debug level rather than an error level (done in L130). If so, the check here should be err == bstructs.ErrPluginShutdown

[preetapan]

I think the comment is correct - its saying that if the err is ErrPluginShutdown we should not be logging because that logging is unnecessary. I am not sure about retrying here vs one layer up to call TaskStats once the plugin restarts though.

Not an expert in this code though, so @nickethier should chime in..

[notnoop]

In the old code, if err != bstructs.ErrPluginShutdown we log in debug mode in L121, but if it's ErrPluginShutdown, then we will log with a Warn level in L130. I'm having a hard time reconciling that with comment.

The old logic for logging is in:

nomad/client/allocrunner/taskrunner/stats_hook.go

Lines 120 to 130 in 8da0b91

	if err != bstructs.ErrPluginShutdown {
	h.logger.Debug("error fetching stats of task", "error", err)
	goto RETRY
	}
	// check if the error is terminal otherwise it's likely a
	// transport error and we should retry
	re, ok = err.(*structs.RecoverableError)
	if ok && re.IsUnrecoverable() {
	return
	}
	h.logger.Warn("stats collection for task failed", "error", err)

[notnoop]

I added a retry check mostly to avoid dealing with integer overflow. If retry count is large enough, we get some wrapping effect, and backoff becomes a negative value! You can see the effects in https://play.golang.org/p/JYvHeAsSTUk .

The backoff computation computes the following backoff value for retry values.

0 	 1s
1 	 4s
2 	 16s
3 	 1m4s
4 	 4m16s
5 	 17m4s
6 	 1h8m16s
7 	 4h33m4s
8 	 18h12m16s
9 	 72h49m4s
10 	 291h16m16s
11 	 1165h5m4s
12 	 4660h20m16s
13 	 18641h21m4s
14 	 74565h24m16s
15 	 298261h37m4s
16 	 1193046h28m16s
17 	 -351909h41m29.709551616s
18 	 -1407638h45m58.838206464s
19 	 -506459h29m21.64327424s

Here, I avoided adding a retry cap to minimize changes compared to old code.

[nickethier]

LGTM on small comment about error handling.

[nickethier]

This error gets swallowed. Is it useful enough to log it even if debug? When callStatsWithRetry is called and returns with an error it just returns.

[notnoop]

yes, we should! I logged them as an error just like the other case where we retry.

[github-actions]

I'm going to lock this pull request because it has been closed for 120 days ⏳. This helps our maintainers find and focus on the active contributions.
If you have found a problem that seems related to this change, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.