From f922e32e31e6125c9a3d27e4ef96f6d7e90583a4 Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Tue, 27 Oct 2026 17:56:58 +0100 Subject: [PATCH 1/5] fix(control): resend the default when an excluded driver returns from an outage A driver excluded for refusing commands while its device was unreachable waited the full 5 min retry window after the device came back, and never got its default again. The inverter kept its last forced battery command for that time. Mark such an exclusion as an outage: reads were failing at exclusion, or the watchdog took the driver offline while it was out. On the first good reading, resend driver_default_mode and let one command through. A device that reads fine and refuses still waits 5 min. Co-Authored-By: Claude Opus 5.5 --- .changeset/c1-default-after-device-returns.md | 10 ++ go/cmd/ftw/driver_failure_default.go | 67 ++++++++-- go/cmd/ftw/driver_failure_default_test.go | 114 ++++++++++++++++++ 3 files changed, 182 insertions(+), 9 deletions(-) create mode 100644 .changeset/c1-default-after-device-returns.md diff --git a/.changeset/c1-default-after-device-returns.md b/.changeset/c1-default-after-device-returns.md new file mode 100644 index 000000000..ebcb562b5 --- /dev/null +++ b/.changeset/c1-default-after-device-returns.md @@ -0,0 +1,10 @@ +--- +"ftw": patch +--- + +Send a battery its default mode again when it comes back from an outage. +A device that refused commands because it was unreachable no longer waits +5 min out of control. On its first good reading FTW resends the default and +lets one command through. Before, an inverter could keep its last forced +charge or discharge for up to 5 min after it came back. A device that reads +fine and keeps refusing still waits 5 min between tries. diff --git a/go/cmd/ftw/driver_failure_default.go b/go/cmd/ftw/driver_failure_default.go index 07e965515..038456ce0 100644 --- a/go/cmd/ftw/driver_failure_default.go +++ b/go/cmd/ftw/driver_failure_default.go @@ -5,6 +5,7 @@ import ( "encoding/json" "errors" "log/slog" + "slices" "sort" "sync" "time" @@ -105,6 +106,13 @@ type refusalState struct { // excludedAt is when the driver was last put out of dispatch, and // zero while it is still in. It dates the retry window. excludedAt time.Time + // outage marks an exclusion that the device's own outage explains: its + // reads were failing when it was excluded, or the watchdog took it + // offline while it was out. Such a device kept the last command it + // accepted and every default write in between failed. When it reads + // again, update resends the default and lets one command through at + // once instead of waiting out driverRefusalRetryInterval. + outage bool } func newDriverActuationTracker(tel *telemetry.Store) *driverActuationTracker { @@ -205,6 +213,7 @@ func (t *driverActuationTracker) recordCommandOutcomeFor(name, action string, er st.excludedAction = action if st.excludedAt.IsZero() { st.excludedAt = now + st.outage = t.unreachable(name) } t.refusals[name] = st t.tel.SetDriverCommandFault(name, true, st.reason) @@ -225,11 +234,20 @@ func (t *driverActuationTracker) recordCommandOutcomeFor(name, action string, er if st.consecutive[action] >= driverRefusalLimit && st.excludedAt.IsZero() { st.excludedAction = action st.excludedAt = now + st.outage = t.unreachable(name) t.tel.SetDriverCommandFault(name, true, st.reason) } t.refusals[name] = st } +// unreachable reports whether the device is out of reach right now: its +// last poll failed or the watchdog has it offline. A refusal then says the +// wire is down, not that the device turns commands away. +func (t *driverActuationTracker) unreachable(name string) bool { + h := t.tel.DriverHealth(name) + return h != nil && (h.Status == telemetry.StatusOffline || h.LastReadFailed()) +} + func dispatchAction(payload []byte) string { var command struct { Action string `json:"action"` @@ -245,7 +263,9 @@ func dispatchAction(payload []byte) string { // update walks every driver that cannot actuate to its autonomous default, // once per transition, and returns the names to send it to. It also ends the -// retry window for drivers excluded long enough to deserve another try. +// retry window for drivers excluded long enough to deserve another try, and +// at once for a driver excluded during an outage that reads again; that +// driver gets its default again too. // // observeOnly drivers are never returned. A telemetry-only driver must // receive no command at all, and that includes the safe one: core has no @@ -259,33 +279,54 @@ func (t *driverActuationTracker) update(now time.Time, observeOnly map[string]bo defer t.mu.Unlock() health := t.tel.AllHealth() + // returned holds drivers back from an outage. Their default went out + // while the device could not take it, so it is sent again this tick. + var returned []string for name, st := range t.refusals { - if _, known := health[name]; !known { + h, known := health[name] + if !known { // Driver removed or restarted: its health record went with // it, and so did the fault. Start it over clean. delete(t.refusals, name) delete(t.defaulted, name) continue } - if st.excludedAt.IsZero() || now.Sub(st.excludedAt) < driverRefusalRetryInterval { + if st.excludedAt.IsZero() { + continue + } + if h.Status == telemetry.StatusOffline && !st.outage { + st.outage = true + t.refusals[name] = st + } + // Only a watchdog offline marks an outage after the exclusion. A + // device that answers and refuses keeps the full window even if + // one of its reads fails meanwhile. + back := st.outage && h.Status != telemetry.StatusOffline && !h.LastReadFailed() + if !back && now.Sub(st.excludedAt) < driverRefusalRetryInterval { continue } - // Retry window is up. Let one command through: a single fresh - // refusal puts the driver straight back out, an accepted one - // clears the record entirely. + // Retry window is up, or the device is back. Let one command + // through: a single fresh refusal puts the driver straight back + // out, an accepted one clears the record entirely. if st.consecutive == nil { st.consecutive = map[string]int{} } st.consecutive[st.excludedAction] = driverRefusalLimit - 1 st.excludedAt = time.Time{} + st.outage = false t.refusals[name] = st t.tel.SetDriverCommandFault(name, false, "") // health holds copies, so apply the release to this tick's // snapshot too — otherwise the latch below reads the driver as // still faulted and defaults a driver we just let back in. - if h, ok := health[name]; ok { - h.SetCommandFault(false, "") - health[name] = h + h.SetCommandFault(false, "") + health[name] = h + if back { + delete(t.defaulted, name) + returned = append(returned, name) + slog.Info("excluded driver reads again after an outage — resending its default and letting one command through", + "driver", name) + continue } slog.Info("driver exclusion retry window elapsed — letting one command through", "driver", name, "window", driverRefusalRetryInterval) @@ -327,6 +368,14 @@ func (t *driverActuationTracker) update(now time.Time, observeOnly map[string]bo } } + // A driver that also flags its own fault was already added above. + for _, name := range returned { + if observeOnly[name] || slices.Contains(pending, name) { + continue + } + pending = append(pending, name) + } + sort.Strings(pending) return pending } diff --git a/go/cmd/ftw/driver_failure_default_test.go b/go/cmd/ftw/driver_failure_default_test.go index 296821484..83fb72268 100644 --- a/go/cmd/ftw/driver_failure_default_test.go +++ b/go/cmd/ftw/driver_failure_default_test.go @@ -294,3 +294,117 @@ func TestRemovedDriverIsForgotten(t *testing.T) { t.Error("removed driver left bookkeeping behind") } } + +// excludeDuringOutage refuses driverRefusalLimit battery commands while the +// device's reads are failing, the way a Sungrow refuses every write while it +// is unreachable, and lets the tracker send its one default. +func excludeDuringOutage(t *testing.T, tel *telemetry.Store, tracker *driverActuationTracker, sender driverCommandSender, now time.Time) { + t.Helper() + payload := []byte(`{"action":"battery","power_w":-3000}`) + tel.RecordDriverError("sungrow", "driver_poll: none of 17 modbus reads returned data") + for i := 0; i < driverRefusalLimit; i++ { + tracker.dispatchCommand(context.Background(), sender, "driver send", "sungrow", payload, time.Second, now) + } + if tel.DriverHealth("sungrow").IsOnline() { + t.Fatal("driver was not excluded") + } + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) +} + +// Random rig seeds 207532–207539 (27 Oct 2026): an inverter outage made the +// Sungrow refuse its battery command and its default, so it was excluded. +// When it came back it still ran its last forced command (187 / 3854 W in +// 207537, from 213 to 510 s) because Core neither resent the default nor +// let a command through until driverRefusalRetryInterval had passed. +func TestDriverExcludedDuringOutageGetsDefaultWhenItReadsAgain(t *testing.T) { + for _, tc := range []struct { + name string + watchdog bool + }{ + {"short outage, reads failing", false}, + {"long outage, watchdog offline", true}, + } { + t.Run(tc.name, func(t *testing.T) { + tel := pollingStore(t, "sungrow") + tracker := newDriverActuationTracker(tel) + now := time.Now() + excludeDuringOutage(t, tel, tracker, refusingSender("modbus reconnect backoff active"), now) + + now = now.Add(10 * time.Second) + if tc.watchdog { + tel.WatchdogScan(time.Nanosecond) + } + if pending := tracker.update(now, nil); len(pending) != 0 { + t.Fatalf("unreachable driver got a second default: %v", pending) + } + + // First fresh reading after the outage. + now = now.Add(20 * time.Second) + tel.RecordDriverSuccess("sungrow") + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + if !tel.DriverHealth("sungrow").IsOnline() { + t.Fatal("driver back from an outage still waits out the retry window") + } + if pending := tracker.update(now.Add(time.Second), nil); len(pending) != 0 { + t.Fatalf("returned driver got its default twice: %v", pending) + } + }) + } +} + +// A device that keeps refusing while it keeps dropping out is retried each +// time it reads again. Once it refuses while reading fine, it waits the full +// retry window like any device that answers and refuses. +func TestDriverRefusingAfterOutageKeepsRetryWindowWhileOnline(t *testing.T) { + tel := pollingStore(t, "sungrow") + tracker := newDriverActuationTracker(tel) + sender := refusingSender("modbus write refused") + payload := []byte(`{"action":"battery","power_w":-3000}`) + now := time.Now() + excludeDuringOutage(t, tel, tracker, sender, now) + + // Back, but the trial command is refused while reads fail again. + now = now.Add(5 * time.Second) + tel.RecordDriverSuccess("sungrow") + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + tel.RecordDriverError("sungrow", "driver_poll: none of 17 modbus reads returned data") + tracker.dispatchCommand(context.Background(), sender, "driver send", "sungrow", payload, time.Second, now) + if tel.DriverHealth("sungrow").IsOnline() { + t.Fatal("refused trial command left the driver in dispatch") + } + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + + // Back again: retried at once, not after the window. + now = now.Add(5 * time.Second) + tel.RecordDriverSuccess("sungrow") + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + if !tel.DriverHealth("sungrow").IsOnline() { + t.Fatal("driver back from a second outage waits out the retry window") + } + + // Now it reads fine and refuses: that is the device's answer. + tracker.dispatchCommand(context.Background(), sender, "driver send", "sungrow", payload, time.Second, now) + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + excludedAt := now + for i := 0; i < 5; i++ { + now = now.Add(time.Minute - time.Second) + // One failed read in between is not an outage. + if i == 2 { + tel.RecordDriverError("sungrow", "one modbus read timed out") + if pending := tracker.update(now, nil); len(pending) != 0 { + t.Fatalf("one failed read sent a default: %v", pending) + } + } + tel.RecordDriverSuccess("sungrow") + if pending := tracker.update(now, nil); len(pending) != 0 { + t.Fatalf("online refusing driver was defaulted again at %v: %v", now.Sub(excludedAt), pending) + } + if tel.DriverHealth("sungrow").IsOnline() { + t.Fatalf("online refusing driver let back in after %v", now.Sub(excludedAt)) + } + } + tracker.update(excludedAt.Add(driverRefusalRetryInterval), nil) + if !tel.DriverHealth("sungrow").IsOnline() { + t.Fatal("retry window elapsed and the driver was not let back in") + } +} From 482d08df259b20288aa364203c6fe041c55d9f39 Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Tue, 27 Oct 2026 18:28:41 +0100 Subject: [PATCH 2/5] fix(control): count a failed read right after the exclusion as an outage A command can reach a dead link before the next poll does. The last read had then succeeded, so the exclusion did not count as an outage, and an outage shorter than the 60 s watchdog never marked it. The driver waited the full 5 min and a Sungrow kept its forced command (rig seed 207536, 29 s outage, 187 / 3000 W held after the return). Store LastSuccess at the exclusion. A failed read with no good read since then is the same outage. A device that has read fine since it refused still keeps the full window. The changeset now says what the return does and does not fix on its own. Co-Authored-By: Claude Opus 5.5 --- .changeset/c1-default-after-device-returns.md | 15 +++-- go/cmd/ftw/driver_failure_default.go | 40 +++++++++++--- go/cmd/ftw/driver_failure_default_test.go | 55 +++++++++++++++++++ 3 files changed, 95 insertions(+), 15 deletions(-) diff --git a/.changeset/c1-default-after-device-returns.md b/.changeset/c1-default-after-device-returns.md index ebcb562b5..c0b1b3bc4 100644 --- a/.changeset/c1-default-after-device-returns.md +++ b/.changeset/c1-default-after-device-returns.md @@ -2,9 +2,12 @@ "ftw": patch --- -Send a battery its default mode again when it comes back from an outage. -A device that refused commands because it was unreachable no longer waits -5 min out of control. On its first good reading FTW resends the default and -lets one command through. Before, an inverter could keep its last forced -charge or discharge for up to 5 min after it came back. A device that reads -fine and keeps refusing still waits 5 min between tries. +Let a battery back into control as soon as it reads again after an outage. +A device that refused commands because it was unreachable, even for less +than a minute, no longer stays out of dispatch for 5 min. On its first good +reading FTW sends its default mode again and takes it back into dispatch, +so FTW's next command reaches it at once. If FTW has no new command for it, +the device keeps whatever it last ran until the default takes hold. On a +Sungrow the resent default does nothing yet, so an old forced command can +still run until FTW sends a new one; that needs a driver fix. A device that +reads fine and keeps refusing still waits 5 min between tries. diff --git a/go/cmd/ftw/driver_failure_default.go b/go/cmd/ftw/driver_failure_default.go index 038456ce0..d45e8f2cf 100644 --- a/go/cmd/ftw/driver_failure_default.go +++ b/go/cmd/ftw/driver_failure_default.go @@ -107,12 +107,18 @@ type refusalState struct { // zero while it is still in. It dates the retry window. excludedAt time.Time // outage marks an exclusion that the device's own outage explains: its - // reads were failing when it was excluded, or the watchdog took it - // offline while it was out. Such a device kept the last command it - // accepted and every default write in between failed. When it reads - // again, update resends the default and lets one command through at - // once instead of waiting out driverRefusalRetryInterval. + // reads were failing when it was excluded, a read failed before any + // good read after it, or the watchdog took it offline while it was + // out. Such a device kept the last command it accepted and every + // default write in between failed. When it reads again, update resends + // the default and lets one command through at once instead of waiting + // out driverRefusalRetryInterval. outage bool + // readAtExclusion is the device's LastSuccess when it was excluded. A + // command can reach a dead link before the next poll does, so the + // first failed read can come just after the exclusion. A failed read + // with no good read since this time is that same outage. + readAtExclusion time.Time } func newDriverActuationTracker(tel *telemetry.Store) *driverActuationTracker { @@ -214,6 +220,7 @@ func (t *driverActuationTracker) recordCommandOutcomeFor(name, action string, er if st.excludedAt.IsZero() { st.excludedAt = now st.outage = t.unreachable(name) + st.readAtExclusion = t.lastRead(name) } t.refusals[name] = st t.tel.SetDriverCommandFault(name, true, st.reason) @@ -235,6 +242,7 @@ func (t *driverActuationTracker) recordCommandOutcomeFor(name, action string, er st.excludedAction = action st.excludedAt = now st.outage = t.unreachable(name) + st.readAtExclusion = t.lastRead(name) t.tel.SetDriverCommandFault(name, true, st.reason) } t.refusals[name] = st @@ -248,6 +256,16 @@ func (t *driverActuationTracker) unreachable(name string) bool { return h != nil && (h.Status == telemetry.StatusOffline || h.LastReadFailed()) } +// lastRead is when the device last delivered fresh telemetry, or zero if it +// never has. +func (t *driverActuationTracker) lastRead(name string) time.Time { + h := t.tel.DriverHealth(name) + if h == nil || h.LastSuccess == nil { + return time.Time{} + } + return *h.LastSuccess +} + func dispatchAction(payload []byte) string { var command struct { Action string `json:"action"` @@ -294,13 +312,17 @@ func (t *driverActuationTracker) update(now time.Time, observeOnly map[string]bo if st.excludedAt.IsZero() { continue } - if h.Status == telemetry.StatusOffline && !st.outage { + // After the exclusion, an outage is the watchdog taking the driver + // offline, or a failed read before any good one. The second covers + // a command that hit the dead link before a poll did, in an outage + // shorter than the watchdog timeout. A device that has read fine + // since it refused keeps the full window, even if a later read + // fails. + noReadSince := h.LastSuccess == nil || !h.LastSuccess.After(st.readAtExclusion) + if !st.outage && (h.Status == telemetry.StatusOffline || (h.LastReadFailed() && noReadSince)) { st.outage = true t.refusals[name] = st } - // Only a watchdog offline marks an outage after the exclusion. A - // device that answers and refuses keeps the full window even if - // one of its reads fails meanwhile. back := st.outage && h.Status != telemetry.StatusOffline && !h.LastReadFailed() if !back && now.Sub(st.excludedAt) < driverRefusalRetryInterval { continue diff --git a/go/cmd/ftw/driver_failure_default_test.go b/go/cmd/ftw/driver_failure_default_test.go index 83fb72268..f46e5823a 100644 --- a/go/cmd/ftw/driver_failure_default_test.go +++ b/go/cmd/ftw/driver_failure_default_test.go @@ -408,3 +408,58 @@ func TestDriverRefusingAfterOutageKeepsRetryWindowWhileOnline(t *testing.T) { t.Fatal("retry window elapsed and the driver was not let back in") } } + +// Rig seeds 207533 and 207536 (27 Oct 2026): the command hit the dead link +// before a poll did, so the last read had succeeded when the driver was +// excluded. In 207536 the outage lasted 29 s, under the 60 s watchdog, and +// the inverter held 187 / 3000 W for the full retry window after it came +// back. A failed read before any good one since the exclusion is the same +// outage. +func TestDriverExcludedJustBeforeShortOutageGetsDefaultWhenItReadsAgain(t *testing.T) { + blocked := errors.Join( + errors.New("driver command may have run: force command write failed: connection refused"), + errors.Join(drivers.ErrControlBlocked, errors.New("driver_default_mode returned false")), + ) + payload := []byte(`{"action":"battery","power_w":-3000}`) + for _, tc := range []struct { + name string + exclude func(*driverActuationTracker, time.Time) + }{ + {"control blocked", func(tracker *driverActuationTracker, now time.Time) { + tracker.recordCommandOutcomeFor("sungrow", "battery", blocked, now) + }}, + {"refused three times", func(tracker *driverActuationTracker, now time.Time) { + sender := refusingSender("force command write failed: connection refused") + for i := 0; i < driverRefusalLimit; i++ { + tracker.dispatchCommand(context.Background(), sender, "driver send", "sungrow", payload, time.Second, now) + } + }}, + } { + t.Run(tc.name, func(t *testing.T) { + tel := pollingStore(t, "sungrow") + tracker := newDriverActuationTracker(tel) + now := time.Now() + tc.exclude(tracker, now) + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + + // Polls fail for 30 s, under the watchdog timeout. + for i := 1; i <= 6; i++ { + tel.RecordDriverError("sungrow", "driver_poll: none of 17 modbus reads returned data") + tel.WatchdogScan(time.Minute) + if pending := tracker.update(now.Add(time.Duration(i)*5*time.Second), nil); len(pending) != 0 { + t.Fatalf("default sent while reads fail: %v", pending) + } + if tel.DriverHealth("sungrow").IsOnline() { + t.Fatal("driver back in dispatch while reads fail") + } + } + + now = now.Add(35 * time.Second) + tel.RecordDriverSuccess("sungrow") + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + if !tel.DriverHealth("sungrow").IsOnline() { + t.Fatalf("driver back from a short outage waits out the %v window", driverRefusalRetryInterval) + } + }) + } +} From 8cf230f14653bca9867de15e8bd5b10297f1ce80 Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Tue, 27 Oct 2026 20:01:11 +0100 Subject: [PATCH 3/5] fix(control): one early trial per refusing driver on a flaky link A failed read right after an exclusion counted as an outage. A device that refuses for real on a flaky link then got a default and a trial command on every good read after a failed one: 75 trials and 150 defaults in 5 min in the new test, instead of one trial per retry window. Once a driver has had its trial and refused it with good reads, a failed read no longer marks an outage. Reads failing at the exclusion and the watchdog taking it offline still do. An accepted trial clears the mark. Co-Authored-By: Claude Opus 5.5 --- go/cmd/ftw/driver_failure_default.go | 14 ++++++-- go/cmd/ftw/driver_failure_default_test.go | 42 +++++++++++++++++++++++ 2 files changed, 54 insertions(+), 2 deletions(-) diff --git a/go/cmd/ftw/driver_failure_default.go b/go/cmd/ftw/driver_failure_default.go index d45e8f2cf..37070b171 100644 --- a/go/cmd/ftw/driver_failure_default.go +++ b/go/cmd/ftw/driver_failure_default.go @@ -119,6 +119,12 @@ type refusalState struct { // first failed read can come just after the exclusion. A failed read // with no good read since this time is that same outage. readAtExclusion time.Time + // retried is set once update has let the driver back in for a trial. + // A trial refused while reads were fine is the device's answer, so a + // failed read after that exclusion does not count as an outage. On a + // flaky link that refuses for real, it would otherwise send a default + // and a trial on every good read after a failed one. + retried bool } func newDriverActuationTracker(tel *telemetry.Store) *driverActuationTracker { @@ -188,6 +194,9 @@ func (t *driverActuationTracker) recordCommandOutcomeFor(name, action string, er if st.excludedAt.IsZero() || action != st.excludedAction { delete(st.consecutive, action) } + if st.excludedAt.IsZero() && action == st.excludedAction { + st.retried = false + } if len(st.consecutive) == 0 { delete(t.refusals, name) } else { @@ -317,9 +326,9 @@ func (t *driverActuationTracker) update(now time.Time, observeOnly map[string]bo // a command that hit the dead link before a poll did, in an outage // shorter than the watchdog timeout. A device that has read fine // since it refused keeps the full window, even if a later read - // fails. + // fails, and so does one that refused its trial with good reads. noReadSince := h.LastSuccess == nil || !h.LastSuccess.After(st.readAtExclusion) - if !st.outage && (h.Status == telemetry.StatusOffline || (h.LastReadFailed() && noReadSince)) { + if !st.outage && (h.Status == telemetry.StatusOffline || (!st.retried && h.LastReadFailed() && noReadSince)) { st.outage = true t.refusals[name] = st } @@ -336,6 +345,7 @@ func (t *driverActuationTracker) update(now time.Time, observeOnly map[string]bo st.consecutive[st.excludedAction] = driverRefusalLimit - 1 st.excludedAt = time.Time{} st.outage = false + st.retried = true t.refusals[name] = st t.tel.SetDriverCommandFault(name, false, "") // health holds copies, so apply the release to this tick's diff --git a/go/cmd/ftw/driver_failure_default_test.go b/go/cmd/ftw/driver_failure_default_test.go index f46e5823a..5ae98b2b5 100644 --- a/go/cmd/ftw/driver_failure_default_test.go +++ b/go/cmd/ftw/driver_failure_default_test.go @@ -463,3 +463,45 @@ func TestDriverExcludedJustBeforeShortOutageGetsDefaultWhenItReadsAgain(t *testi }) } } + +// A device that refuses for real on a flaky link: it is excluded with good +// reads, the next read fails, and it gets its one early trial on the good +// read after. It refuses that trial while reading fine. From then on a +// failed read between good ones is the link, not an outage, so it waits the +// full retry window instead of getting a default and a trial on every good +// read after a failed one. +func TestDriverRefusingOnFlakyLinkGetsOneEarlyTrial(t *testing.T) { + tel := pollingStore(t, "sungrow") + tracker := newDriverActuationTracker(tel) + sender := refusingSender("modbus write refused") + payload := []byte(`{"action":"battery","power_w":-3000}`) + now := time.Now() + for i := 0; i < driverRefusalLimit; i++ { + tracker.dispatchCommand(context.Background(), sender, "driver send", "sungrow", payload, time.Second, now) + } + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + + // Within one retry window of the first exclusion, the early trial + // comes 4 s in and its window has not elapsed by the end. + end := now.Add(driverRefusalRetryInterval) + trials, defaults := 0, 0 + for now.Before(end) { + now = now.Add(2 * time.Second) + tel.RecordDriverError("sungrow", "one modbus read timed out") + if pending := tracker.update(now, nil); len(pending) != 0 { + t.Fatalf("default sent while a read failed: %v", pending) + } + now = now.Add(2 * time.Second) + time.Sleep(time.Millisecond) // LastSuccess is wall time + tel.RecordDriverSuccess("sungrow") + defaults += len(tracker.update(now, nil)) + if tel.DriverHealth("sungrow").IsOnline() { + trials++ + tracker.dispatchCommand(context.Background(), sender, "driver send", "sungrow", payload, time.Second, now) + defaults += len(tracker.update(now, nil)) + } + } + if trials != 1 || defaults != 2 { + t.Fatalf("refusing driver on a flaky link got %d trials and %d defaults inside the retry window, want 1 and 2", trials, defaults) + } +} From eb53c05c55bcc477429a08335f0f85a796fd9e18 Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Tue, 27 Oct 2026 20:14:26 +0100 Subject: [PATCH 4/5] fix(control): end the early-trial guard after one retry interval The retried flag only cleared when the excluded action was accepted. A driver back from an outage that dispatch then left idle kept it with no end, so its next short dead-link outage was not counted as one and the inverter held its last command for the full 5 min window (207535, 207536). Store when the trial began and let the guard lapse after driverRefusalRetryInterval. Co-Authored-By: Claude Opus 5.5 --- go/cmd/ftw/driver_failure_default.go | 25 +++++--- go/cmd/ftw/driver_failure_default_test.go | 75 +++++++++++++++++++++++ 2 files changed, 90 insertions(+), 10 deletions(-) diff --git a/go/cmd/ftw/driver_failure_default.go b/go/cmd/ftw/driver_failure_default.go index 37070b171..a7761def8 100644 --- a/go/cmd/ftw/driver_failure_default.go +++ b/go/cmd/ftw/driver_failure_default.go @@ -119,12 +119,15 @@ type refusalState struct { // first failed read can come just after the exclusion. A failed read // with no good read since this time is that same outage. readAtExclusion time.Time - // retried is set once update has let the driver back in for a trial. - // A trial refused while reads were fine is the device's answer, so a - // failed read after that exclusion does not count as an outage. On a - // flaky link that refuses for real, it would otherwise send a default - // and a trial on every good read after a failed one. - retried bool + // retriedAt is when update last let the driver back in for a trial. + // A trial refused while reads were fine is the device's answer, so for + // one retry interval after it a failed read does not count as an + // outage. On a flaky link that refuses for real, it would otherwise + // send a default and a trial on every good read after a failed one. + // It ends after that interval, or when the excluded action is + // accepted, so a later outage counts again even if dispatch sent the + // driver nothing in between. + retriedAt time.Time } func newDriverActuationTracker(tel *telemetry.Store) *driverActuationTracker { @@ -195,7 +198,7 @@ func (t *driverActuationTracker) recordCommandOutcomeFor(name, action string, er delete(st.consecutive, action) } if st.excludedAt.IsZero() && action == st.excludedAction { - st.retried = false + st.retriedAt = time.Time{} } if len(st.consecutive) == 0 { delete(t.refusals, name) @@ -326,9 +329,11 @@ func (t *driverActuationTracker) update(now time.Time, observeOnly map[string]bo // a command that hit the dead link before a poll did, in an outage // shorter than the watchdog timeout. A device that has read fine // since it refused keeps the full window, even if a later read - // fails, and so does one that refused its trial with good reads. + // fails, and so does one that refused a trial with good reads + // less than one retry interval after the trial began. noReadSince := h.LastSuccess == nil || !h.LastSuccess.After(st.readAtExclusion) - if !st.outage && (h.Status == telemetry.StatusOffline || (!st.retried && h.LastReadFailed() && noReadSince)) { + recentTrial := !st.retriedAt.IsZero() && now.Sub(st.retriedAt) < driverRefusalRetryInterval + if !st.outage && (h.Status == telemetry.StatusOffline || (!recentTrial && h.LastReadFailed() && noReadSince)) { st.outage = true t.refusals[name] = st } @@ -345,7 +350,7 @@ func (t *driverActuationTracker) update(now time.Time, observeOnly map[string]bo st.consecutive[st.excludedAction] = driverRefusalLimit - 1 st.excludedAt = time.Time{} st.outage = false - st.retried = true + st.retriedAt = now t.refusals[name] = st t.tel.SetDriverCommandFault(name, false, "") // health holds copies, so apply the release to this tick's diff --git a/go/cmd/ftw/driver_failure_default_test.go b/go/cmd/ftw/driver_failure_default_test.go index 5ae98b2b5..66af98c9f 100644 --- a/go/cmd/ftw/driver_failure_default_test.go +++ b/go/cmd/ftw/driver_failure_default_test.go @@ -505,3 +505,78 @@ func TestDriverRefusingOnFlakyLinkGetsOneEarlyTrial(t *testing.T) { t.Fatalf("refusing driver on a flaky link got %d trials and %d defaults inside the retry window, want 1 and 2", trials, defaults) } } + +// A driver back from a dead-link outage may get no command for the excluded +// action for minutes (dispatch idle: 207535 showed status.dispatch empty for +// 67 s). Its next short outage, a command refused on the dead link before a +// poll fails (207536), must count as an outage again once the trial guard +// has run out, or the device holds its last command for the full window. +// Inside one retry interval of the trial the guard still holds: that is the +// flaky-link storm TestDriverRefusingOnFlakyLinkGetsOneEarlyTrial covers. +func TestSecondDeadLinkOutageAfterReturnGetsDefault(t *testing.T) { + payload := []byte(`{"action":"battery","power_w":-3000}`) + for _, tc := range []struct { + name string + accepted bool + gap time.Duration + wantBack bool + }{ + {"dispatch idle 6 min between outages", false, 6 * time.Minute, true}, + {"battery command accepted between outages", true, time.Minute, true}, + {"dispatch idle 1 min between outages", false, time.Minute, false}, + } { + t.Run(tc.name, func(t *testing.T) { + tel := pollingStore(t, "sungrow") + tracker := newDriverActuationTracker(tel) + now := time.Now() + excludeDuringOutage(t, tel, tracker, refusingSender("modbus reconnect backoff active"), now) + + now = now.Add(20 * time.Second) + time.Sleep(time.Millisecond) // LastSuccess is wall time + tel.RecordDriverSuccess("sungrow") + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + if tc.accepted { + tracker.dispatchCommand(context.Background(), &stubSender{}, "driver send", "sungrow", payload, time.Second, now) + } + for end := now.Add(tc.gap); now.Before(end); { + now = now.Add(5 * time.Second) + time.Sleep(time.Millisecond) + tel.RecordDriverSuccess("sungrow") + if p := tracker.update(now, nil); len(p) != 0 { + t.Fatalf("default while healthy: %v", p) + } + } + + dead := refusingSender("force command write failed: connection refused") + for i := 0; i < driverRefusalLimit && tel.DriverHealth("sungrow").IsOnline(); i++ { + tracker.dispatchCommand(context.Background(), dead, "driver send", "sungrow", payload, time.Second, now) + } + if tel.DriverHealth("sungrow").IsOnline() { + t.Fatal("dead-link refusals did not exclude the driver") + } + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + for i := 1; i <= 6; i++ { + tel.RecordDriverError("sungrow", "driver_poll: none of 17 modbus reads returned data") + tel.WatchdogScan(time.Minute) + if p := tracker.update(now.Add(time.Duration(i)*5*time.Second), nil); len(p) != 0 { + t.Fatalf("default while reads fail: %v", p) + } + } + now = now.Add(35 * time.Second) + time.Sleep(time.Millisecond) + tel.RecordDriverSuccess("sungrow") + got := tracker.update(now, nil) + if !tc.wantBack { + assertStringsEqual(t, got, nil) + if tel.DriverHealth("sungrow").IsOnline() { + t.Fatal("driver let back in within one retry interval of its last trial") + } + return + } + assertStringsEqual(t, got, []string{"sungrow"}) + if !tel.DriverHealth("sungrow").IsOnline() { + t.Fatalf("driver back from a 29 s outage waits out the %v window", driverRefusalRetryInterval) + } + }) + } +} From 91fb66a7aa473036ec9478f48b57fa608a7f7ef7 Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Wed, 28 Oct 2026 01:43:05 +0100 Subject: [PATCH 5/5] test(control): accepted trial ends the early-trial guard A hybrid inverter's curtail streak can keep the refusal record alive after its battery trial was accepted. The new test checks that a dead-link outage a minute later still gets the default and a trial on return. Removing the retriedAt reset makes it fail; no other test catches that. Co-Authored-By: Claude Opus 5.5 --- go/cmd/ftw/driver_failure_default_test.go | 55 +++++++++++++++++++++++ 1 file changed, 55 insertions(+) diff --git a/go/cmd/ftw/driver_failure_default_test.go b/go/cmd/ftw/driver_failure_default_test.go index 66af98c9f..9b47b3e2e 100644 --- a/go/cmd/ftw/driver_failure_default_test.go +++ b/go/cmd/ftw/driver_failure_default_test.go @@ -580,3 +580,58 @@ func TestSecondDeadLinkOutageAfterReturnGetsDefault(t *testing.T) { }) } } + +// An accepted command for the excluded action ends the trial guard at once. +// On a hybrid inverter a curtail streak can keep the refusal record alive +// after the battery trial was accepted. A dead-link outage a minute later is +// then a new outage, so the device gets its default when it reads again +// instead of waiting out the retry window. +func TestAcceptedTrialEndsGuardWhileOtherActionStreakRemains(t *testing.T) { + tel := pollingStore(t, "sungrow") + tracker := newDriverActuationTracker(tel) + battery := []byte(`{"action":"battery","power_w":-3000}`) + curtail := []byte(`{"action":"curtail","power_limit_w":2500}`) + now := time.Now() + excludeDuringOutage(t, tel, tracker, refusingSender("modbus reconnect backoff active"), now) + + now = now.Add(20 * time.Second) + time.Sleep(time.Millisecond) // LastSuccess is wall time + tel.RecordDriverSuccess("sungrow") + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + tracker.dispatchCommand(context.Background(), refusingSender("curtail register refused"), "pv curtail send", "sungrow", curtail, time.Second, now) + tracker.dispatchCommand(context.Background(), &stubSender{}, "driver send", "sungrow", battery, time.Second, now) + if _, kept := tracker.refusals["sungrow"]; !kept { + t.Fatal("curtail streak did not keep the refusal record") + } + for end := now.Add(time.Minute); now.Before(end); { + now = now.Add(5 * time.Second) + time.Sleep(time.Millisecond) + tel.RecordDriverSuccess("sungrow") + if p := tracker.update(now, nil); len(p) != 0 { + t.Fatalf("default while healthy: %v", p) + } + } + + dead := refusingSender("force command write failed: connection refused") + for i := 0; i < driverRefusalLimit; i++ { + tracker.dispatchCommand(context.Background(), dead, "driver send", "sungrow", battery, time.Second, now) + } + if tel.DriverHealth("sungrow").IsOnline() { + t.Fatal("dead-link refusals did not exclude the driver") + } + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + for i := 1; i <= 6; i++ { + tel.RecordDriverError("sungrow", "driver_poll: none of 17 modbus reads returned data") + tel.WatchdogScan(time.Minute) + if p := tracker.update(now.Add(time.Duration(i)*5*time.Second), nil); len(p) != 0 { + t.Fatalf("default while reads fail: %v", p) + } + } + now = now.Add(35 * time.Second) + time.Sleep(time.Millisecond) + tel.RecordDriverSuccess("sungrow") + assertStringsEqual(t, tracker.update(now, nil), []string{"sungrow"}) + if !tel.DriverHealth("sungrow").IsOnline() { + t.Fatalf("driver back from a 29 s outage waits out the %v window", driverRefusalRetryInterval) + } +}