diff --git a/core/services/relay/evm/mercury/wsrpc/cache/cache.go b/core/services/relay/evm/mercury/wsrpc/cache/cache.go index cab5654081b..181900bc15c 100644 --- a/core/services/relay/evm/mercury/wsrpc/cache/cache.go +++ b/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,11 +236,13 @@ 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() @@ -246,6 +250,7 @@ func (m *memCache) LatestReport(ctx context.Context, req *pb.LatestReportRequest } // 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 diff --git a/core/services/relay/evm/mercury/wsrpc/client.go b/core/services/relay/evm/mercury/wsrpc/client.go index 5cdf1f44e96..5b6bfa1a9b0 100644 --- a/core/services/relay/evm/mercury/wsrpc/client.go +++ b/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 }