diff --git a/.changeset/c1-default-after-device-returns.md b/.changeset/c1-default-after-device-returns.md new file mode 100644 index 000000000..c0b1b3bc4 --- /dev/null +++ b/.changeset/c1-default-after-device-returns.md @@ -0,0 +1,13 @@ +--- +"ftw": patch +--- + +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 07e965515..a7761def8 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,28 @@ 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, 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 + // 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 { @@ -174,6 +197,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.retriedAt = time.Time{} + } if len(st.consecutive) == 0 { delete(t.refusals, name) } else { @@ -205,6 +231,8 @@ func (t *driverActuationTracker) recordCommandOutcomeFor(name, action string, er st.excludedAction = action 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) @@ -225,11 +253,31 @@ 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) + st.readAtExclusion = t.lastRead(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()) +} + +// 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"` @@ -245,7 +293,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 +309,61 @@ 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 + } + // 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, 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) + 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 + } + 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 + st.retriedAt = now 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 +405,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..9b47b3e2e 100644 --- a/go/cmd/ftw/driver_failure_default_test.go +++ b/go/cmd/ftw/driver_failure_default_test.go @@ -294,3 +294,344 @@ 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") + } +} + +// 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) + } + }) + } +} + +// 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) + } +} + +// 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) + } + }) + } +} + +// 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) + } +}