HTTP plugin: warn on uncached repeated GET requests (#31932)

plugin/http.go

@@ -27,6 +27,7 @@ type HTTP struct {
 	body        string
 	pipeline    *pipeline.Pipeline
 	mu          *sync.Mutex
+	log         *util.Logger
 }
 
 func init() {
@@ -100,6 +101,7 @@ func NewHTTP(log *util.Logger, method, uri string, insecure bool, cache time.Dur
 		Helper: request.NewHelper(log),
 		url:    uri,
 		method: method,
+		log:    log,
 	}
 
 	// build the cache stack without logging so the logging tripper
@@ -219,6 +221,11 @@ func (p *HTTP) request(url string, body string) ([]byte, error) {
 		return []byte{}, err
 	}
 
+	// warn on uncached GET polling: a configured cache would spare the roundtrip
+	if key := stripQuery(url); p.method == http.MethodGet && p.mu == nil && repeatedGet(key, time.Now()) {
+		p.log.WARN.Printf("uncached request repeated within 1s, please report at https://github.com/evcc-io/evcc/issues: %s", key)
+	}
+
 	val, err := p.DoBody(req)
 	if err != nil {
 		if err2 := knownErrors(val); err2 != nil {
@@ -229,6 +236,37 @@ func (p *HTTP) request(url string, body string) ([]byte, error) {
 	return val, err
 }
 
+type httpAccess struct {
+	last   time.Time
+	warned bool
+}
+
+var (
+	httpSeenMu sync.Mutex
+	httpSeen   = make(map[string]httpAccess)
+)
+
+// stripQuery drops the query and fragment so cache-busting params do not make
+// each poll look like a distinct url.
+func stripQuery(url string) string {
+	if i := strings.IndexAny(url, "?#"); i >= 0 {
+		return url[:i]
+	}
+	return url
+}
+
+// repeatedGet reports the first time url is fetched again within a second, a sign
+// the response should be cached. It fires once per url to avoid log spam.
+func repeatedGet(url string, now time.Time) bool {
+	httpSeenMu.Lock()
+	defer httpSeenMu.Unlock()
+
+	a, seen := httpSeen[url]
+	warn := seen && !a.warned && now.Sub(a.last) < time.Second
+	httpSeen[url] = httpAccess{last: now, warned: a.warned || warn}
+	return warn
+}
+
 var _ Getters = (*HTTP)(nil)
 
 // StringGetter sends string request

plugin/http_test.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/evcc-io/evcc/util"
 	"github.com/samber/lo"
+	"github.com/stretchr/testify/require"
 	"github.com/stretchr/testify/suite"
 )
 
@@ -162,3 +163,21 @@ func (suite *httpTestSuite) TestSetPath() {
 	suite.Require().NoError(s("4711"))
 	suite.Require().Equal("/foo/bar/4711", suite.h.req.URL.String())
 }
+
+func TestRepeatedGet(t *testing.T) {
+	url := "http://repeated.test/uncached"
+	t0 := time.Now()
+
+	require.False(t, repeatedGet(url, t0))                           // first sighting
+	require.True(t, repeatedGet(url, t0.Add(500*time.Millisecond)))  // repeated within 1s: warn
+	require.False(t, repeatedGet(url, t0.Add(600*time.Millisecond))) // already warned: silent
+
+	spaced := "http://repeated.test/spaced"
+	require.False(t, repeatedGet(spaced, t0))
+	require.False(t, repeatedGet(spaced, t0.Add(2*time.Second))) // >1s apart: no warn
+
+	// query params are stripped before keying, so cache-busting still counts as a repeat
+	require.Equal(t, "http://q.test/path", stripQuery("http://q.test/path?ts=1&x=2#frag"))
+	require.False(t, repeatedGet(stripQuery("http://q.test/path?ts=1"), t0))
+	require.True(t, repeatedGet(stripQuery("http://q.test/path?ts=2"), t0.Add(300*time.Millisecond)))
+}