Improve logging for cache (#11453)

* Include ServerURL in cache logging

* Add additional cache tracing

* TEMP - DO NOT MERGE THIS - promote Trace=>Debug cache logging

* Log if call was cached or not

* Revert "TEMP - DO NOT MERGE THIS - promote Trace=>Debug cache logging"

This reverts commit f0f3f07a59c8d310ac74849519d46ea9b53495c1.

core/services/relay/evm/mercury/wsrpc/cache/cache.go

@@ -213,12 +213,14 @@ func (m *memCache) LatestReport(ctx context.Context, req *pb.LatestReportRequest
 	if time.Now().Before(v.expiresAt) {
 		// CACHE HIT
 		promCacheHitCount.WithLabelValues(m.client.ServerURL(), feedIDHex).Inc()
+		m.lggr.Tracew("LatestReport CACHE HIT (hot path)", "feedID", feedIDHex)
 
 		defer v.RUnlock()
 		return v.val, nil
 	} else if v.fetching {
 		// CACHE WAIT
 		promCacheWaitCount.WithLabelValues(m.client.ServerURL(), feedIDHex).Inc()
+		m.lggr.Tracew("LatestReport CACHE WAIT (hot path)", "feedID", feedIDHex)
 		// if someone else is fetching then wait for the fetch to complete
 		ch := v.fetchCh
 		v.RUnlock()
@@ -234,18 +236,21 @@ func (m *memCache) LatestReport(ctx context.Context, req *pb.LatestReportRequest
 	if time.Now().Before(v.expiresAt) {
 		// CACHE HIT
 		promCacheHitCount.WithLabelValues(m.client.ServerURL(), feedIDHex).Inc()
+		m.lggr.Tracew("LatestReport CACHE HIT (cold path)", "feedID", feedIDHex)
 		defer v.RUnlock()
 		return v.val, nil
 	} else if v.fetching {
 		// CACHE WAIT
 		promCacheWaitCount.WithLabelValues(m.client.ServerURL(), feedIDHex).Inc()
+		m.lggr.Tracew("LatestReport CACHE WAIT (cold path)", "feedID", feedIDHex)
 		// if someone else is fetching then wait for the fetch to complete
 		ch := v.fetchCh
 		v.Unlock()
 		return v.waitForResult(ctx, ch, m.chStop)
 	}
 	// CACHE MISS
 	promCacheMissCount.WithLabelValues(m.client.ServerURL(), feedIDHex).Inc()
+	m.lggr.Tracew("LatestReport CACHE MISS (cold path)", "feedID", feedIDHex)
 	// initiate the fetch and wait for result
 	ch := v.initiateFetch()
 	v.Unlock()
@@ -328,7 +333,7 @@ func (m *memCache) fetch(req *pb.LatestReportRequest, v *cacheVal) {
 
 func (m *memCache) Start(context.Context) error {
 	return m.StartOnce(m.Name(), func() error {
-		m.lggr.Debugw("MemCache starting", "config", m.cfg)
+		m.lggr.Debugw("MemCache starting", "config", m.cfg, "serverURL", m.client.ServerURL())
 		m.wg.Add(1)
 		go m.runloop()
 		return nil

core/services/relay/evm/mercury/wsrpc/client.go

@@ -303,17 +303,21 @@ func (w *client) LatestReport(ctx context.Context, req *pb.LatestReportRequest)
 	if err = w.waitForReady(ctx); err != nil {
 		return nil, errors.Wrap(err, "LatestReport failed")
 	}
+	var cached bool
 	if w.cache == nil {
 		resp, err = w.rawClient.LatestReport(ctx, req)
 	} else {
+		cached = true
 		resp, err = w.cache.LatestReport(ctx, req)
 	}
 	if err != nil {
-		lggr.Errorw("LatestReport failed", "err", err, "resp", resp)
+		lggr.Errorw("LatestReport failed", "err", err, "resp", resp, "cached", cached)
 	} else if resp.Error != "" {
-		lggr.Errorw("LatestReport failed; mercury server returned error", "err", resp.Error, "resp", resp)
+		lggr.Errorw("LatestReport failed; mercury server returned error", "err", resp.Error, "resp", resp, "cached", cached)
+	} else if !cached {
+		lggr.Debugw("LatestReport succeeded", "resp", resp, "cached", cached)
 	} else {
-		lggr.Debugw("LatestReport succeeded", "resp", resp)
+		lggr.Tracew("LatestReport succeeded", "resp", resp, "cached", cached)
 	}
 	return
 }