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 {