Fix cache meta trace tags

Currently the meta is attempted to be logged in a hit span that may or
may not exist (or has not started) depending on the cache phase.

3 files changed, 15 insertions, 6 deletions

diff --git a/.bleep b/.bleep
index 1e3b918..a4e0bfa 100644
--- a/.bleep
+++ b/.bleep
@@ -1 +1 @@
-4a86ea20bc7d70669a7be7b3b316139cbe74e648
\ No newline at end of file
+6917c93caac52f862080f3b1572efdc2e82f21b0
\ No newline at end of file
diff --git a/pingora-cache/src/lib.rs b/pingora-cache/src/lib.rs
index a82c799..6bebbd3 100644
--- a/pingora-cache/src/lib.rs
+++ b/pingora-cache/src/lib.rs
@@ -492,14 +492,14 @@ impl HttpCache {
                         inner.lock = Some(lock.lock(key));
                     }
                 }
-                inner.traces.log_meta(&meta);
+                inner.traces.start_hit_span(phase, hit_status);
+                inner.traces.log_meta_in_hit_span(&meta);
                 if let Some(eviction) = inner.eviction {
                     // TODO: make access() accept CacheKey
                     let cache_key = key.to_compact();
                     // FIXME: get size
                     eviction.access(&cache_key, 0, meta.0.internal.fresh_until);
                 }
-                inner.traces.start_hit_span(phase, hit_status);
                 inner.meta = Some(meta);
                 inner.body_reader = Some(hit_handler);
             }
@@ -717,7 +717,8 @@ impl HttpCache {
             // TODO: store the staled meta somewhere else for future use?
             CachePhase::Stale | CachePhase::Miss => {
                 let inner = self.inner_mut();
-                inner.traces.log_meta(&meta);
+                // TODO: have a separate expired span?
+                inner.traces.log_meta_in_miss_span(&meta);
                 inner.meta = Some(meta);
             }
             _ => panic!("wrong phase {:?}", self.phase),
diff --git a/pingora-cache/src/trace.rs b/pingora-cache/src/trace.rs
index c385aea..58f3511 100644
--- a/pingora-cache/src/trace.rs
+++ b/pingora-cache/src/trace.rs
@@ -74,14 +74,14 @@ impl CacheTraceCTX {
         self.hit_span.set_finish_time(SystemTime::now);
     }
 
-    pub fn log_meta(&mut self, meta: &CacheMeta) {
+    fn log_meta(span: &mut Span, meta: &CacheMeta) {
         fn ts2epoch(ts: SystemTime) -> f64 {
             ts.duration_since(SystemTime::UNIX_EPOCH)
                 .unwrap_or_default() // should never overflow but be safe here
                 .as_secs_f64()
         }
         let internal = &meta.0.internal;
-        self.hit_span.set_tags(|| {
+        span.set_tags(|| {
             [
                 Tag::new("created", ts2epoch(internal.created)),
                 Tag::new("fresh_until", ts2epoch(internal.fresh_until)),
@@ -95,4 +95,12 @@ impl CacheTraceCTX {
             ]
         });
     }
+
+    pub fn log_meta_in_hit_span(&mut self, meta: &CacheMeta) {
+        CacheTraceCTX::log_meta(&mut self.hit_span, meta);
+    }
+
+    pub fn log_meta_in_miss_span(&mut self, meta: &CacheMeta) {
+        CacheTraceCTX::log_meta(&mut self.miss_span, meta);
+    }
 }