pillar: retry deferred info messages the controller may still accept - #6304
Conversation
Codecov Report❌ Patch coverage is Additional details and impacted files@@ Coverage Diff @@
## master #6304 +/- ##
==========================================
+ Coverage 24.61% 25.06% +0.45%
==========================================
Files 506 516 +10
Lines 93048 94839 +1791
==========================================
+ Hits 22900 23774 +874
- Misses 68318 69064 +746
- Partials 1830 2001 +171 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
6201ddd to
3eb3394
Compare
|
Claude finished @rene's task in 4m 22s —— View job Review
I reviewed the production changes (
Nothing blocking. The evetest fault proxy and controller-fault tests look reasonable (rules copied under lock, admin API path shielded, |
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
| if rv.HTTPResp != nil && rv.HTTPResp.StatusCode >= 200 && | ||
| rv.HTTPResp.StatusCode < 300 { | ||
| combinedRV.Status = rv.Status |
There was a problem hiding this comment.
This "delivered by this port, so report its status" fix only copies rv.Status for 2xx, but SendOnIntf treats 200/201/304/204 as delivered success (line 894 here, and it now sets rv.Status = SenderStatusNone for all of them). 304 Not Modified is a real controller response (unchanged config), and 204 is covered while 304 is not.
So when an earlier port failed (setting combinedRV.Status to e.g. SenderStatusUpgrade from a 503) and a later port delivers a 304, this branch is skipped and combinedRV.Status keeps the stale failure status even though the request was delivered. For the deferred queue that surfaces as sendItem hitting the rv.Status != SenderStatusNone case and treating a successful delivery as a failure (itemStopPass). Consider matching the set SendOnIntf accepts rather than a bare 2xx:
| if rv.HTTPResp != nil && rv.HTTPResp.StatusCode >= 200 && | |
| rv.HTTPResp.StatusCode < 300 { | |
| combinedRV.Status = rv.Status | |
| if rv.HTTPResp != nil && (rv.HTTPResp.StatusCode == http.StatusOK || | |
| rv.HTTPResp.StatusCode == http.StatusCreated || | |
| rv.HTTPResp.StatusCode == http.StatusNotModified || | |
| rv.HTTPResp.StatusCode == http.StatusNoContent) { | |
| combinedRV.Status = rv.Status | |
| } |
| if sameContent(q.deferredItems[ind].buf, buf) { | ||
| item.attempts = q.deferredItems[ind].attempts | ||
| item.retryAt = q.deferredItems[ind].retryAt | ||
| } |
There was a problem hiding this comment.
Minor: this retry-state inheritance only applies while the item is still in q.deferredItems. During a handleDeferred pass the item is checked out into reqs, so a concurrent SetDeferred for the same key finds no existing entry and adds a fresh item (attempts=0, retryAt zero). mergeQueuesNoLock then replaces the retried notSentReqs entry with that fresh one, dropping its attempts/retryAt.
Net effect: an object republishing identical bytes at the wrong moment can reset its backoff and hide the accumulated attempt count — the case this comment says is preserved. Narrow/racy, but worth either preserving the retry state in mergeQueuesNoLock when sameContent holds, or softening the guarantee here.
There was a problem hiding this comment.
The fresh seems the better behavior - want to give the last update N tries.
| // harness keeps talking to Adam directly on the internal port, so reading what | ||
| // the controller knows is never affected by an injected fault. | ||
| // Must be called before Start. | ||
| func (ac *AdamClient) EnableFaultInjection() { |
There was a problem hiding this comment.
Would it hurt to always run this proxy and have fault injections available for any test?
I mean, if test does not configure any faults, then everything behaves as normally, no?
There was a problem hiding this comment.
Yes, it would work, and the cost is small — but so is the benefit: always-on
only saves a suite from calling EnableControllerFaults(). The cost, by
contrast, is paid in every unrelated test's failure analysis - did the proxy (passing through)
cause the test to fail or not?
Would it make sense to move this from a per-suite call to a harness-level env var/flag, defaulted off?
There was a problem hiding this comment.
OK, yes I think EVETEST_<something> variable to enable/disable this would make sense.
I would like to keep evetest.Init() as the first evetest function call always in every test(suite).
There was a problem hiding this comment.
Done - EVETEST_CONTROLLER_FAULTS, off by default:
EVETEST_CONTROLLER_FAULTS=true make evetest NAME=TestControllerFaultsSuite
EnableControllerFaults() is gone, so evetest.Init() is the first evetest call in every test again. Without the variable the devices reach Adam directly and these tests skip, naming the variable in the skip message; the README documents it under Debugging Variables.
With it set, Adam moves to loopback and the proxy takes over the device-facing addresses, so an injected fault cannot be sidestepped by reaching the controller directly:
Adam process started and listening on IPs:[127.0.0.1], port:443
Fault proxy listening on 245.245.245.245:443, forwarding to 127.0.0.1:443
Fault proxy listening on [fd24:1ac2:e355::1]:443, forwarding to 127.0.0.1:443
Both paths were run on amd64 under QEMU after rebasing onto master: with the variable the suite is green (897.91s), and without it TestBootstrapWithProxy still onboards through the SDN's transparent MITM proxy with no fault proxy in the path at all. Note that whatever runs these in CI has to set the variable explicitly, or the coverage silently disappears behind a skip.
milan-zededa
left a comment
milan-zededa
left a comment
There was a problem hiding this comment.
This enhancement makes sense to me, but given how vulnerable and critical for EVE these deferred queues are, I’d suggest holding off on backporting it until it has been thoroughly tested on master.
Only added one question regarding the Adam proxy.
Makes sense. I'll park the backport PRs in draft state with a note. |
82abfb8 to
4eb11b8
Compare
SendOnAllIntf hands back the HTTP response only when a send succeeded, or when the caller asked to stop at the first port that answered with an error. When it walks every port and none of them delivers, the status the server did answer with is lost, leaving the caller unable to tell a rejection by the controller from a link that never got there. Carry the last status code seen in the return value so that a caller can base a retry decision on it. Signed-off-by: eriknordmark <erik@zededa.com> Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: eriknordmark <erik@zededa.com>
A device reports application, volume, content tree, blob, network instance, hardware and cluster state to the controller only when that state changes; nothing re-asserts it later. Yet any status between 400 and 599 made the deferred queue log one line and then treat the message as if it had been delivered, so a few seconds of controller-side trouble left the controller's view of an object wrong until the object next changed - possibly never. The discard was introduced for a controller that no longer knows about an object and therefore rejects the request itself; server errors were swept into it when the same flag started meaning "do not try the other ports". Decide from the status code instead. A rejection of the request is still given up on, now logged as an error since the state it carried is lost for good. Anything the controller may yet accept - a server error, a rate limit, or a refusal to authorize the device, which EVE answers by restarting attestation - keeps the message queued and offers it again with a growing delay. There is no attempt limit: a message this queue carries has no other path to the controller, so the only alternative to retrying is losing it. Since a status code means the controller was reached, the failure belongs to that one message and the rest of the pass now continues, where before a single refused item aborted the pass for every remaining item and priority class and was then retried ahead of them all. A message waiting out its delay moves behind its peers, so one object cannot hold up the reports for all the others. Failures are reported to the sent-callback with a real status, so a message the controller refused is no longer recorded as sent. Retrying without end must not be silent, so a backlog of undelivered messages and an individual message the controller keeps refusing are both raised as warnings. Reporting an object again with unchanged content keeps the retry state of the queued message, so that a device republishing the same bytes neither restarts the delay nor hides how long the message has been stuck. That leaves the two flags with one meaning each: BailOnHTTPErr says how many ports to try, exactly as in RequestOptions, and DiscardOnFailure - which used to be called IgnoreErr, having never ignored an error - says that a payload is superseded by the next periodic one and so is not worth keeping. Signed-off-by: eriknordmark <erik@zededa.com> Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The first edgeview status, the one that tells the controller edgeview is active, was routed to the best-effort periodic queue in the hope of getting it delivered - which had the opposite effect, since that queue discards a message whose send fails instead of retrying it. It now takes the same path as every other info message, where a controller-side failure is retried. That leaves location info as the only user of the periodic queue, so also correct its description: metrics and hardware health never went through a deferred queue, and NTP sources deliberately use the reliable one. Signed-off-by: eriknordmark <erik@zededa.com> Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: eriknordmark <erik@zededa.com>
While walking the management ports, any non-zero sender status picked up on the way was kept in the return value, including when a later port went on to deliver the request. The caller then saw a successful send described by the complaint of a port that failed - the deferred queue treated such a message as not sent and kept it queued for another try, so a report that did reach the controller could be sent a second time, and a config fetch that succeeded on the second port still logged a controller upgrade. Report the status of the attempt that produced the response. Within a port this restores an invariant that already held one branch away: on any non-2xx response the status collected from the source addresses tried earlier is already discarded, and only the branch for a delivered response kept it. Nothing is lost for diagnosis, since every certificate and connection failure is logged where it happens. When no port delivers the request the collected status still stands, which is what tells a caller that the controller rejected the request rather than being unreachable. Signed-off-by: eriknordmark <erik@zededa.com> Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: eriknordmark <erik@zededa.com>
Making EVE face a controller which fails in a particular way was not expressible: the network model can impair a link, but nothing could make the controller answer a chosen status, and how EVE handles the answers it gets is exactly what several parts of the device reporting path turn on. A test suite can now ask for the controller to run behind a proxy which answers, delays or drops selected device requests, and arm or clear those faults as the test goes. Only what the devices send is affected: the harness reaches the controller on its own port, so reading back what the controller knows is never disturbed by an injected fault, and a rule can only match the device API, never the admin one. The proxy presents the controller's own certificate to the devices and verifies the controller's certificate in turn, so the connection is no less protected than without it. Signed-off-by: eriknordmark <erik@zededa.com> Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: eriknordmark <erik@zededa.com>
Application state reaches the controller only when it changes, so whether a report survives a controller that will not take it decides whether the controller's view of an application is right or stale indefinitely. Three tests deploy an application, make the controller fail the info messages that report it, and change its state while it cannot be reported. Two require the controller to catch up on its own once it accepts messages again: one where it answered a server error, one where it could not be reached at all. Both hold the fault until the state transition has had time to complete - a report produced after the controller is healthy again would be delivered whatever the queue does with a refused one, so clearing the fault early would prove nothing - and then allow for the retry delay the device has reached by that point. The third covers a rejection, where the report is deliberately given up on. The state it carried is never told to the controller, and an application which has settled produces no further report to carry it, so this one watches the device information instead: EVE re-sends that on a timer even when nothing changed, which shows the queue still delivering after messages were dropped, without depending on how long an application takes to stop. Signed-off-by: eriknordmark <erik@zededa.com> Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
4eb11b8 to
4cceea5
Compare
Controller fault injection is asked for with EVETEST_CONTROLLER_FAULTS, a harness-level switch, which keeps evetest.Init the first evetest call in every test and lets any test arm a fault. It is off by default: with nothing armed the proxy forwards every request unchanged, but it terminates TLS and re-originates the request, so leaving it out of the path unless a test needs it keeps an unrelated failure one suspect fewer. A test which arms faults skips when it is off, naming the variable. With the proxy in front of it, Adam listens on loopback rather than on the addresses the devices route to, so an injected fault cannot be sidestepped by reaching the controller directly; the harness verifies the controller's hostname so that it can still reach Adam at an address the certificate does not name. Proxy errors reach the harness log rather than the global standard logger, and a proxy which fails to take its port no longer leaves Adam running behind it, unreachable and holding its database directory. Signed-off-by: eriknordmark <erik@zededa.com> Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
4cceea5 to
a6bff41
Compare
3 participants
Description
This bug has been present for a while, and I discovered it by chance due to long running sequence of old tests running and one failing and that failure correlated with the controller being updated and restarted. Turns out that the app INFO message with its latest RUNNING status was never delivered to the controller even though those should be reliably delivered. Details below.
Note that this deferrred queue has been a source of issues in the past so this is a somewhat risky fix. To balance that, the fix relaxed the ordering so that if some message sees failures from the controller (due to some bug), it should not result in blocking the sending of the other info messages.
Separately there is an EVE API PR lf-edge/eve-api#154 to add some more metrics around these failures and deferred queuing to get better visibility in production systems.
A device tells the controller about an application, volume, content tree,
blob, network instance, hardware or cluster change only when that change
happens; nothing re-asserts the state afterwards. Yet the deferred queue
treated any HTTP status from 400 to 599 as a reason to throw the message
away, logging a single line at the lowest severity and then counting the
message as sent. A few seconds of controller-side trouble was therefore
enough to leave the controller's view of an object wrong until that object
next changed - for a steady-state application, possibly never.
A case in point is a 503 error when the controller is updating; post update the controller will have missed any updates for these object.
The discard was introduced in 2018 for a controller that no longer knows
about an object and rejects the request itself (
return400, matching exactly400). Server errors were swept into it in 2020 by a commit whose subject was
about not trying the other ports on a 503; the same commit attached the
comment "Return 4xx and 5xx without trying other interfaces" to the shared
flag, which is why the field has documented the port-selection behavior while
the queue silently discarded data ever since.
This PR decides retention from the status code:
413, 415, 422 - and is now logged as an error, since the state it carried is
lost for good.
errors, rate limiting, request timeout, and a refusal to authenticate or
authorize the device, which EVE itself answers by restarting attestation and
by fetching new controller certificates. There is no attempt limit; a
message this queue carries has no other route to the controller, so the only
alternative to retrying is losing it.
Retrying safely required fixing the queue ordering as well, which is the
larger half of the change. A status code means the controller was reached, so
the failure belongs to that one message: the pass now continues instead of
aborting for every remaining message and every lower-priority class, and a
message waiting out its retry delay moves behind its peers rather than being
retried ahead of them. Without this, converting the discard into a retry would
have traded data loss for one object blocking the reports of all the others.
Because retrying forever must not be silent, a long backlog of undelivered
messages and an individual message the controller keeps refusing are both
raised as warnings. Reporting an object again with unchanged content keeps the
retry state of the queued message, so a device republishing identical bytes
neither restarts the delay nor hides how long a message has been stuck.
Two smaller things fall out of the above.
SendOnAllIntfnow reports thesender status of the port that actually delivered a request rather than a
complaint collected from a port that did not, so a delivered report is no
longer kept and sent a second time. And the first edgeview status no longer
takes a special path: it was routed to the best-effort queue in the hope of
getting it delivered, which had the opposite effect, since that queue discards
a message whose send fails.
Fixes #6302
How to test and validate this PR
Covered by automated unit tests in
pkg/pillar/controllerconn: 30 tests, runwith
make -C pkg/pillar testorgo test -race ./controllerconn/.... Theycover the status classification, the per-item delay, the demotion behind peers,
the interaction with the attest / app-info / hardware-info priority classes,
the two warnings, the retry state of a republished payload, and the queue
length staying bounded by the number of objects. Each was checked against the
pre-change behavior: reverting the classification or the pass-continuation
makes them fail on their assertions rather than pass silently.
It is also covered end to end.
evetestcan put the controller behind a proxywhich answers, delays or drops selected device requests - asked for with
EVETEST_CONTROLLER_FAULTS=true, and out of the path otherwise. Thenevetest/tests/controllerfaultsuses that: an application's state is changedwhile the controller fails the info messages reporting it, and the controller
then has to catch up on its own. Run with
Without the variable the controller is reached directly and these tests skip.
The outcome is measured rather than argued.
TestInfoRetriedAfterServerErrorfails against an EVE built without this change - the proxy answered every
info message with 503, so the device did try, and then nothing arrived in the
eight minutes after the controller started accepting messages again, the report
being gone for good - and passes against one built with it. The suite is
green as a whole on amd64 under QEMU:
Only the first of the three distinguishes this change; the other two guard
behavior it deliberately preserves - a controller which cannot be reached keeps
the message queued, and one which rejects it drops the message without leaving
the queue unable to deliver what follows.
Changelog notes
Device state updates - application, volume, content tree, network instance,
hardware and cluster information - are no longer discarded when the controller
answers with a temporary error such as a 503 during an upgrade or an overload.
They are retried until the controller accepts them, so its view of a device no
longer stays stale after a brief interruption. Messages the controller rejects
outright are still discarded, now with an error logged.
PR Backports
The bug is present on all four branches, but the queue-ordering half of the fix
changes behavior in code which has been fragile before, so the backports wait
until this has soaked on master for a while. Review asked for the same.
Checklist
I've provided a proper description
I've added the proper documentation
I've tested my PR on amd64 device
I've tested my PR on arm64 device
I've written the test verification instructions
I've set the proper labels to this PR
I've checked the boxes above, or I've provided a good reason why I didn't
check them: the tests above ran on an amd64 QEMU device rather than hardware,
and the arm64 box is unchecked for want of one. Nothing here is architecture
specific.