Skip to content

Commit 60303cc

Browse files
frahlgclaude
andauthored
fix(forecast): save the forecast identity outside the lock (#1883)
RefreshIdentity held forecastSiteConfig.mu across two SaveConfig calls, each up to 5 s against a busy SQLite writer. The control tick's Snapshot waited behind them. Compute under the lock, save after it, and wait 30 s before retrying a failed binding save. Configure's weather generation save moves out of the lock the same way. Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
1 parent 10de589 commit 60303cc

3 files changed

Lines changed: 141 additions & 12 deletions

File tree

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
---
2+
"ftw": patch
3+
---
4+
5+
Keep the control loop on time while the forecast saves its device identity. The save no longer holds the lock the control loop reads, so a busy database can no longer delay control by up to 10 seconds. After a failed save, wait 30 seconds before trying again instead of retrying every second.
Lines changed: 102 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,102 @@
1+
package main
2+
3+
import (
4+
"database/sql"
5+
"path/filepath"
6+
"testing"
7+
"time"
8+
9+
"github.com/srcfl/ftw/go/internal/state"
10+
_ "modernc.org/sqlite"
11+
)
12+
13+
// RefreshIdentity must not hold forecastSiteConfig.mu while SaveConfig waits
14+
// for the SQLite write lock, or the tick's Snapshot() waits with it.
15+
func TestForecastSnapshotDoesNotWaitForIdentitySave(t *testing.T) {
16+
path := filepath.Join(t.TempDir(), "state.db")
17+
st, err := state.Open(path)
18+
if err != nil {
19+
t.Fatal(err)
20+
}
21+
defer st.Close()
22+
23+
s := &forecastSiteConfig{
24+
store: st,
25+
baseRevision: "base",
26+
required: map[string]bool{"meter": false},
27+
identity: func(string) (string, bool) { return "serial:ABC123", true },
28+
configuredAt: time.Now().Add(-time.Minute),
29+
}
30+
31+
// Another writer (rolloff, backup, history writer) holds the WAL write lock.
32+
other, err := sql.Open("sqlite", path+"?_pragma=busy_timeout(5000)")
33+
if err != nil {
34+
t.Fatal(err)
35+
}
36+
defer other.Close()
37+
other.SetMaxOpenConns(1)
38+
tx, err := other.Begin()
39+
if err != nil {
40+
t.Fatal(err)
41+
}
42+
if _, err := tx.Exec(`UPDATE config SET value = value WHERE 0`); err != nil {
43+
t.Fatal(err)
44+
}
45+
46+
refreshDone := make(chan time.Duration, 1)
47+
go func() {
48+
start := time.Now()
49+
s.RefreshIdentity(time.Now())
50+
refreshDone <- time.Since(start)
51+
}()
52+
time.Sleep(100 * time.Millisecond) // RefreshIdentity now waits in SaveConfig
53+
54+
start := time.Now()
55+
_ = s.Snapshot() // what the control tick does before persistTelemetryTick
56+
blocked := time.Since(start)
57+
_ = tx.Rollback()
58+
refresh := <-refreshDone
59+
t.Logf("Snapshot waited %v; RefreshIdentity took %v", blocked, refresh)
60+
if blocked > time.Second {
61+
t.Fatalf("tick Snapshot blocked %v behind identity SaveConfig held under forecast lock", blocked)
62+
}
63+
}
64+
65+
// A failed binding save stays dirty and waits forecastBindingRetry before the
66+
// next attempt, instead of retrying on every 1 s identity poll.
67+
func TestForecastIdentityBindingSaveBacksOffAfterFailure(t *testing.T) {
68+
path := filepath.Join(t.TempDir(), "state.db")
69+
broken, err := state.Open(path)
70+
if err != nil {
71+
t.Fatal(err)
72+
}
73+
_ = broken.Close() // every save now fails
74+
75+
s := &forecastSiteConfig{
76+
store: broken,
77+
baseRevision: "base",
78+
required: map[string]bool{"meter": false},
79+
identity: func(string) (string, bool) { return "serial:ABC123", true },
80+
configuredAt: time.Now().Add(-time.Minute),
81+
}
82+
now := time.Now()
83+
s.RefreshIdentity(now)
84+
if !s.bindingDirty {
85+
t.Fatal("failed binding save was marked clean")
86+
}
87+
88+
st, err := state.Open(path)
89+
if err != nil {
90+
t.Fatal(err)
91+
}
92+
defer st.Close()
93+
s.store = st
94+
s.RefreshIdentity(now.Add(time.Second))
95+
if _, ok := st.LoadConfig(forecastIdentityReceiptKey); ok || !s.bindingDirty {
96+
t.Fatal("binding save retried inside the back-off window")
97+
}
98+
s.RefreshIdentity(now.Add(forecastBindingRetry))
99+
if _, ok := st.LoadConfig(forecastIdentityReceiptKey); !ok || s.bindingDirty {
100+
t.Fatal("binding save not retried after the back-off window")
101+
}
102+
}

‎go/cmd/ftw/forecast_site.go‎

Lines changed: 34 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@ type forecastSiteConfig struct {
3434
required map[string]bool // value identifies PV sources
3535
accepted forecastIdentityReceipt
3636
bindingDirty bool
37+
bindingRetryAt time.Time // a failed binding save waits until then
3738
configuredAt time.Time
3839
heatingPrior, ratedPV float64
3940
annualBase float64
@@ -49,6 +50,10 @@ type forecastIdentityReceipt struct {
4950

5051
const forecastIdentityReceiptKey = "forecast/live_identity_v1"
5152

53+
// forecastBindingRetry spaces out binding saves after a failure. Each attempt
54+
// can wait seconds on SQLite, and the identity poll runs every second.
55+
const forecastBindingRetry = 30 * time.Second
56+
5257
// forecastPipelinePolicy names how Core composes the forecast it plans with.
5358
// The evaluation cohort keys on it rather than on the Core version, so error
5459
// bands and baselines survive updates that leave forecasting alone. Bump it
@@ -137,6 +142,7 @@ func (s *forecastSiteConfig) Configure(cfg *config.Config, catalog []drivers.Cat
137142
}
138143
weatherData, _ := json.Marshal(weather)
139144
weatherRevision := fmt.Sprintf("%x", sha256.Sum256(weatherData))
145+
var weatherReceipt []byte
140146
s.mu.Lock()
141147
for _, old := range earlier {
142148
if err != nil || old == baseRevision || s.accepted.BaseRevision != old {
@@ -152,13 +158,10 @@ func (s *forecastSiteConfig) Configure(cfg *config.Config, catalog []drivers.Cat
152158
if s.weatherRevision != weatherRevision || s.weatherSinceMS <= 0 {
153159
s.weatherRevision = weatherRevision
154160
s.weatherSinceMS = time.Now().UnixMilli()
155-
receipt, _ := json.Marshal(struct {
161+
weatherReceipt, _ = json.Marshal(struct {
156162
Revision string
157163
SinceMS int64
158164
}{weatherRevision, s.weatherSinceMS})
159-
if err := s.store.SaveConfig("forecast/weather_generation", string(receipt)); err != nil {
160-
slog.Warn("forecast weather generation not saved", "err", err)
161-
}
162165
}
163166
v.WeatherSinceMS = s.weatherSinceMS
164167
v.SiteID = s.value.SiteID
@@ -190,6 +193,12 @@ func (s *forecastSiteConfig) Configure(cfg *config.Config, catalog []drivers.Cat
190193
}{weather, s.annualBase, s.annualIncludesHeating})
191194
s.priorRevision = fmt.Sprintf("%x", sha256.Sum256(priorData))
192195
s.mu.Unlock()
196+
// Save outside s.mu: the control tick reads Snapshot and must not wait on SQLite.
197+
if weatherReceipt != nil {
198+
if err := s.store.SaveConfig("forecast/weather_generation", string(weatherReceipt)); err != nil {
199+
slog.Warn("forecast weather generation not saved", "err", err)
200+
}
201+
}
193202
s.RefreshIdentity(time.Now())
194203
return previous != s.Snapshot().Revision
195204
}
@@ -198,10 +207,10 @@ func (s *forecastSiteConfig) Configure(cfg *config.Config, catalog []drivers.Cat
198207
// Serial/MAC identities are usable immediately. Endpoint fallback retains the
199208
// existing device contract after a short init grace. A previously stronger
200209
// identity must return before it can qualify again after restart.
201-
// Caller serializes this with model rebinding under forecastConfigMu.
210+
// Caller serializes this with model rebinding under forecastConfigMu, so the
211+
// saves below, made outside s.mu, keep their order.
202212
func (s *forecastSiteConfig) RefreshIdentity(now time.Time) bool {
203213
s.mu.Lock()
204-
defer s.mu.Unlock()
205214
ids := make(map[string]string, len(s.required))
206215
pending, pvPending := false, false
207216
for name, isPV := range s.required {
@@ -250,12 +259,25 @@ func (s *forecastSiteConfig) RefreshIdentity(now time.Time) bool {
250259
s.accepted.LearningBaseRevision = learningBase
251260
}
252261
s.bindingDirty = true
253-
if encoded, err := json.Marshal(s.accepted); err == nil {
254-
if err = s.store.SaveConfig(forecastIdentityReceiptKey, string(encoded)); err != nil {
255-
slog.Warn("forecast identity binding not saved", "err", err)
256-
} else {
257-
s.bindingDirty = false
258-
}
262+
}
263+
var binding []byte
264+
if !pending && s.bindingDirty && !now.Before(s.bindingRetryAt) {
265+
binding, _ = json.Marshal(s.accepted)
266+
}
267+
s.mu.Unlock()
268+
269+
// Save outside s.mu: the control tick reads Snapshot and must not wait on SQLite.
270+
if binding != nil {
271+
err := s.store.SaveConfig(forecastIdentityReceiptKey, string(binding))
272+
s.mu.Lock()
273+
if err != nil {
274+
s.bindingRetryAt = now.Add(forecastBindingRetry)
275+
} else {
276+
s.bindingDirty = false
277+
}
278+
s.mu.Unlock()
279+
if err != nil {
280+
slog.Warn("forecast identity binding not saved", "err", err, "retry_in", forecastBindingRetry)
259281
}
260282
}
261283
if changed {

0 commit comments

Comments
 (0)