From 36a9dcf36fe16c1b7884602b376ee6c6ad3126fc Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Sat, 26 Sep 2026 08:57:30 +0200 Subject: [PATCH] fix(control,prices): stop logging normal operation as warnings A night on the home box logged 3,022 warnings, of which 2,960 were "dispatch: meter clamp reduced battery target" and 9 were Nord Pool's 204 for tomorrow before 13:00. Both are normal operation, and they buried the one warning that mattered (the Easee cloud outage). - The meter clamp logs at info when it engages and at debug while it stays engaged. A dispatch tick past the holdoff that does not clamp ends the episode (deferred, so every exit after the holdoff counts, including the deadband exit); holdoff ticks do not. - A failed fetch of tomorrow's prices before 13:05 Europe/Stockholm logs at debug. dayAheadPublished is shared with nextDayAheadCatch. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01MuerPFZFG88kgu8sWVHeq7 --- .changeset/quiet-normal-logs.md | 5 +++ go/internal/control/control_test.go | 69 +++++++++++++++++++++++++++++ go/internal/control/dispatch.go | 20 ++++++++- go/internal/prices/nordpool_test.go | 26 +++++++++++ go/internal/prices/prices.go | 30 ++++++++++--- 5 files changed, 142 insertions(+), 8 deletions(-) create mode 100644 .changeset/quiet-normal-logs.md diff --git a/.changeset/quiet-normal-logs.md b/.changeset/quiet-normal-logs.md new file mode 100644 index 00000000..13982918 --- /dev/null +++ b/.changeset/quiet-normal-logs.md @@ -0,0 +1,5 @@ +--- +"ftw": patch +--- + +The log no longer fills with warnings about normal operation. The meter clamp, which holds the grid at its target and stops the battery from exporting while covering the house, is logged once when it engages instead of as a warning every control tick. On the home box that was about 3,000 warnings a night. A failed fetch of tomorrow's prices before they are published, around 13:00, is logged at debug level; a failure for today, or for tomorrow after publication, is still a warning. Real warnings, such as a cloud charger going offline, stand out again in `journalctl` and in the support report. diff --git a/go/internal/control/control_test.go b/go/internal/control/control_test.go index 62a2a8d6..29be6aab 100644 --- a/go/internal/control/control_test.go +++ b/go/internal/control/control_test.go @@ -1,6 +1,8 @@ package control import ( + "context" + "log/slog" "math" "testing" "time" @@ -6503,3 +6505,70 @@ func TestSelfConsumptionEVReserveReleasesToBatteryWhenEVCannotStart(t *testing.T t.Errorf("TargetW=%.0f — battery must absorb the sub-reserve surplus the EV can't use; want a positive charge (~1100), got idle", targets[0].TargetW) } } + +// Holding the grid at its target is normal operation. The clamp is reported +// when it engages, once, and each further tick stays at debug level; it +// engages again only after a tick without it. +func TestMeterClampLogsWhenItEngages(t *testing.T) { + var levels []slog.Level + previous := slog.Default() + slog.SetDefault(slog.New(levelRecorder{levels: &levels})) + defer slog.SetDefault(previous) + + clampTick := func(st *State) { + store := seedStore(2000, []struct { + name string + currentW, soc float64 + }{{"ferroamp", 0, 0.6}}) + for i := 0; i < 200; i++ { + st.PI.Update(2000) + } + st.LastDispatch = nil // each call is a fresh control tick, past the holdoff + ComputeDispatch(store, st, caps(map[string]float64{"ferroamp": 15200}), 11040) + } + st := NewState(0, 50, "ferroamp") + st.Mode = ModePeakShaving + st.PeakLimitW = 0 + st.SlewRateW = 100000 + + clampTick(st) + clampTick(st) + clampTick(st) + want := []slog.Level{slog.LevelInfo, slog.LevelDebug, slog.LevelDebug} + if len(levels) != len(want) { + t.Fatalf("clamp logged %d times at %v, want %v", len(levels), levels, want) + } + for i := range want { + if levels[i] != want[i] { + t.Fatalf("clamp log levels = %v, want %v", levels, want) + } + } + + // A tick with the grid on target needs no clamp and ends the episode. + quiet := seedStore(0, []struct { + name string + currentW, soc float64 + }{{"ferroamp", 0, 0.6}}) + st.PI.Reset() + st.LastDispatch = nil + ComputeDispatch(quiet, st, caps(map[string]float64{"ferroamp": 15200}), 11040) + if st.meterClampLogged { + t.Fatal("a tick without the clamp left it marked as reported") + } + clampTick(st) + if last := levels[len(levels)-1]; last != slog.LevelInfo { + t.Fatalf("a clamp that engages again logged at %v, want INFO", last) + } +} + +type levelRecorder struct{ levels *[]slog.Level } + +func (levelRecorder) Enabled(context.Context, slog.Level) bool { return true } +func (r levelRecorder) Handle(_ context.Context, rec slog.Record) error { + if rec.Message == "dispatch: meter clamp reduced battery target" { + *r.levels = append(*r.levels, rec.Level) + } + return nil +} +func (r levelRecorder) WithAttrs([]slog.Attr) slog.Handler { return r } +func (r levelRecorder) WithGroup(string) slog.Handler { return r } diff --git a/go/internal/control/dispatch.go b/go/internal/control/dispatch.go index 80bf3ee8..d2273de1 100644 --- a/go/internal/control/dispatch.go +++ b/go/internal/control/dispatch.go @@ -1,6 +1,7 @@ package control import ( + "context" "encoding/json" "fmt" "log/slog" @@ -473,6 +474,9 @@ type State struct { // PI controller (outer, site-level) PI *PIController + // meterClampLogged records that the live-meter clamp was already + // reported, so it is logged when it engages rather than every tick. + meterClampLogged bool // Slew + holdoff SlewRateW float64 @@ -1638,6 +1642,12 @@ func ComputeDispatch( } } + // Every tick past the holdoff decides afresh whether the live-meter + // clamp is engaged, so one that ends without it ends the episode and + // the next engagement is reported again. + var meterClampActive bool + defer func() { state.meterClampLogged = meterClampActive }() + // ---- Read site meter ---- rawGridW := 0.0 if r := store.Get(state.SiteMeterDriver, telemetry.DerMeter); r != nil { @@ -1782,7 +1792,6 @@ func ComputeDispatch( // removed that motion. A non-following battery would otherwise recreate // the unsafe command on every tick (#816). var meterClampMoveW float64 - var meterClampActive bool switch { case manualHoldActive: // Drive the aggregate battery toward the operator's setpoint. @@ -2260,7 +2269,14 @@ func ComputeDispatch( if allowed != targetTotal { meterClampActive = true meterClampMoveW = allowed - currentTotal - slog.Warn("dispatch: meter clamp reduced battery target", + // Holding the grid at its target is normal operation, not a + // fault: report when the clamp engages and keep the per-tick + // detail at debug level. + level := slog.LevelDebug + if !state.meterClampLogged { + level = slog.LevelInfo + } + slog.Log(context.Background(), level, "dispatch: meter clamp reduced battery target", "requested_total_w", targetTotal, "clamped_total_w", allowed, "ideal_target_w", idealTarget, diff --git a/go/internal/prices/nordpool_test.go b/go/internal/prices/nordpool_test.go index 811bd0ee..83dcd81d 100644 --- a/go/internal/prices/nordpool_test.go +++ b/go/internal/prices/nordpool_test.go @@ -122,6 +122,32 @@ func TestNextDayAheadCatch(t *testing.T) { } } +// Asking for tomorrow before about 13:00 finds nothing on a normal day; only +// a failure after publication, or for today, is worth a warning. +func TestNotPublishedYet(t *testing.T) { + loc, err := time.LoadLocation("Europe/Stockholm") + if err != nil { + t.Fatal(err) + } + for _, tc := range []struct { + name string + offset int + now time.Time + want bool + }{ + {"tomorrow in the morning", 1, time.Date(2026, 9, 26, 7, 40, 0, 0, loc), true}, + {"tomorrow just after midnight", 1, time.Date(2026, 9, 26, 0, 40, 0, 0, loc), true}, + {"tomorrow after publication", 1, time.Date(2026, 9, 26, 13, 30, 0, 0, loc), false}, + {"tomorrow in winter, UTC clock", 1, time.Date(2026, 12, 1, 11, 30, 0, 0, time.UTC), true}, + {"tomorrow in winter after publication, UTC clock", 1, time.Date(2026, 12, 1, 12, 30, 0, 0, time.UTC), false}, + {"today", 0, time.Date(2026, 9, 26, 7, 40, 0, 0, loc), false}, + } { + if got := notPublishedYet(tc.offset, tc.now); got != tc.want { + t.Errorf("%s: notPublishedYet = %v, want %v", tc.name, got, tc.want) + } + } +} + func TestNordPoolRejectsCurrencyMismatch(t *testing.T) { srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { _ = json.NewEncoder(w).Encode(map[string]any{ diff --git a/go/internal/prices/prices.go b/go/internal/prices/prices.go index bc069895..51687b89 100644 --- a/go/internal/prices/prices.go +++ b/go/internal/prices/prices.go @@ -693,16 +693,28 @@ func (s *Service) loop(ctx context.Context) { // day-ahead is normally on the dataportal. Hourly ticks alone can miss // that window for up to an hour. func nextDayAheadCatch(now time.Time) time.Time { + target := dayAheadPublished(now) + if !now.Before(target) { + target = target.Add(24 * time.Hour) + } + return target +} + +// notPublishedYet reports whether a failed fetch for today+offset is the +// normal answer before tomorrow's day-ahead prices are published. +func notPublishedYet(offset int, now time.Time) bool { + return offset == 1 && now.Before(dayAheadPublished(now)) +} + +// dayAheadPublished is 13:05 Europe/Stockholm on now's date, by when +// tomorrow's day-ahead prices are normally published. +func dayAheadPublished(now time.Time) time.Time { loc, err := time.LoadLocation("Europe/Stockholm") if err != nil { loc = time.FixedZone("CET", 3600) } now = now.In(loc) - target := time.Date(now.Year(), now.Month(), now.Day(), 13, 5, 0, 0, loc) - if !now.Before(target) { - target = target.Add(24 * time.Hour) - } - return target + return time.Date(now.Year(), now.Month(), now.Day(), 13, 5, 0, 0, loc) } func (s *Service) fetchAndStore(ctx context.Context) { @@ -711,7 +723,13 @@ func (s *Service) fetchAndStore(ctx context.Context) { day := now.AddDate(0, 0, offset) rows, err := s.Provider.Fetch(ctx, s.Zone, day) if err != nil { - slog.Warn("price fetch failed", "zone", s.Zone, "day", day.Format("2006-01-02"), "err", err) + // Tomorrow's day-ahead is not published before about 13:00, so + // asking earlier is expected to find nothing. + if notPublishedYet(offset, now) { + slog.Debug("tomorrow's prices are not published yet", "zone", s.Zone, "day", day.Format("2006-01-02"), "err", err) + } else { + slog.Warn("price fetch failed", "zone", s.Zone, "day", day.Format("2006-01-02"), "err", err) + } continue } if len(rows) == 0 {