Add (relative) microsecond timestamps to traces

diff --git a/pdns/logger.cc b/pdns/logger.cc
index 8d34e1ca4c9afca870b22363c42cde9332668542..e290a2c9e6a3515afb0e356cafa98679b4b4b9a7 100644 (file)
--- a/pdns/logger.cc
+++ b/pdns/logger.cc
@@ -202,3 +202,17 @@ Logger& Logger::operator<<(const ComboAddress& ca)
   *this << ca.toLogString();
   return *this;
 }
+
+#ifdef RECURSOR
+void addTraceTS(const timeval& start, ostringstream& str)
+{
+  const auto & content = str.str();
+  if (content.empty() || content.at(content.size() - 1) == '\n') {
+    timeval time{};
+    gettimeofday(&time, nullptr);
+    auto elapsed = time - start;
+    auto diff = elapsed.tv_sec * 1000000 + static_cast<time_t>(elapsed.tv_usec);
+    str << diff << ' ';
+  }
+}
+#endif

diff --git a/pdns/logger.hh b/pdns/logger.hh
index d05b5327449ae850d74e1e35217d2c9a376aa7c6..61ef70a00c0a6bee0b89f83d836bf6fe58585c1c 100644 (file)
--- a/pdns/logger.hh
+++ b/pdns/logger.hh
@@ -176,23 +176,29 @@ Logger& getLogger();
 struct LogVariant
 {
   string prefix;
+  timeval start;
   // variant cannot hold references
   std::variant<Logger*, ostringstream*> v;
 };
 
 using OptLog = std::optional<LogVariant>;
 
+
 #ifndef RECURSOR
 // Originally there was a flag but it was never set from !RECURSOR
 #define VLOG(log, x) VLOG only works in recursor
 #else
-#define VLOG(log, x)                                                       \
-  if (log) {                                                               \
-    if (std::holds_alternative<Logger*>((log)->v)) {                       \
+
+void addTraceTS(const timeval& start, ostringstream& str);
+
+#define VLOG(log, x)                                                    \
+  if (log) {                                                            \
+    if (std::holds_alternative<Logger*>((log)->v)) {                      \
       *std::get<Logger*>(log->v) << Logger::Warning << (log)->prefix << x; \
-    }                                                                      \
-    else if (std::holds_alternative<ostringstream*>((log)->v)) {           \
-      *std::get<ostringstream*>((log)->v) << (log)->prefix << x;           \
-    }                                                                      \
+    }                                                                   \
+    else if (std::holds_alternative<ostringstream*>((log)->v)) {        \
+      addTraceTS((log)->start, *std::get<ostringstream*>((log)->v));    \
+      *std::get<ostringstream*>((log)->v) << (log)->prefix << x;        \
+    }                                                                   \
   }
 #endif

diff --git a/pdns/recursordist/pdns_recursor.cc b/pdns/recursordist/pdns_recursor.cc
index 6eea0fd44411299d549a9b7213c545150abd8198..1d7ddd6ce000fbe0b706278ece539dd409304657 100644 (file)
--- a/pdns/recursordist/pdns_recursor.cc
+++ b/pdns/recursordist/pdns_recursor.cc
@@ -838,11 +838,15 @@ static bool isEnabledForUDRs(const std::shared_ptr<std::vector<std::unique_ptr<F
 }
 #endif // HAVE_FSTRM
 
-static void dumpTrace(const string& trace)
+const char* timestamp(const struct timeval& tv, char* buf, size_t sz);
+
+static void dumpTrace(const string& trace, const timeval& timev)
 {
   if (trace.empty()) {
     return;
   }
+  timeval now{};
+  Utility::gettimeofday(&now);
   int traceFd = dup(t_tracefd);
   if (traceFd == -1) {
     int err = errno;
@@ -858,14 +862,12 @@ static void dumpTrace(const string& trace)
     close(traceFd);
     return;
   }
-  vector<string> lines;
-  boost::split(lines, trace, boost::is_any_of("\n"));
-  int count = 0;
-  for (const string& line : lines) {
-    if (!line.empty())
-      fprintf(filep.get(), "%04d %s\n", ++count, line.c_str());
-  }
-  fprintf(filep.get(), "\n");
+  std::array<char, 64> timebuf;
+  timestamp(timev, timebuf.data(), timebuf.size());
+  fprintf(filep.get(), " us === START OF TRACE %s ===\n", timebuf.data());
+  fprintf(filep.get(), "%s", trace.c_str());
+  timestamp(now, timebuf.data(), timebuf.size());
+  fprintf(filep.get(), "=== END OF TRACE %s ===\n", timebuf.data());
   // fclose by unique_ptr does implicit flush
 }
 
@@ -1092,7 +1094,6 @@ void startDoResolve(void* p)
     if (t_traceRegex && t_traceRegex->match(dc->d_mdp.d_qname.toString())) {
       sr.setLogMode(SyncRes::Store);
       tracedQuery = true;
-      sr.setId("T");
     }
 
     if (!g_quiet || tracedQuery) {
@@ -1313,7 +1314,7 @@ void startDoResolve(void* p)
 
   haveAnswer:;
     if (tracedQuery || res == -1 || res == RCode::ServFail || pw.getHeader()->rcode == RCode::ServFail) {
-      dumpTrace(sr.getTrace());
+      dumpTrace(sr.getTrace(), sr.d_fixednow);
     }
 
     if (res == -1) {

diff --git a/pdns/recursordist/syncres.cc b/pdns/recursordist/syncres.cc
index 9601120506900086a99cdac1ccaadbadffaca926..1fa55f37c08c772c2c191d2459f151ea1b1d2f22 100644 (file)
--- a/pdns/recursordist/syncres.cc
+++ b/pdns/recursordist/syncres.cc
@@ -469,22 +469,23 @@ bool SyncRes::s_save_parent_ns_set;
 unsigned int SyncRes::s_max_busy_dot_probes;
 bool SyncRes::s_addExtendedResolutionDNSErrors;
 
-#define LOG(x)                     \
-  if (d_lm == Log) {               \
-    g_log << Logger::Warning << x; \
-  }                                \
-  else if (d_lm == Store) {        \
-    d_trace << x;                  \
+#define LOG(x)                                  \
+  if (d_lm == Log) {                            \
+    g_log << Logger::Warning << x;              \
+  }                                             \
+  else if (d_lm == Store) {                     \
+    addTraceTS(d_fixednow, d_trace);            \
+    d_trace << x;                               \
   }
 
 OptLog SyncRes::LogObject(const string& prefix)
 {
   OptLog ret;
   if (d_lm == Log) {
-    ret = {prefix, &g_log};
+    ret = {prefix, d_fixednow, &g_log};
   }
   else if (d_lm == Store) {
-    ret = {prefix, &d_trace};
+    ret = {prefix, d_now, &d_trace};
   }
   return ret;
 }
@@ -517,7 +518,8 @@ static inline void accountAuthLatency(uint64_t usec, int family)
 }
 
 SyncRes::SyncRes(const struct timeval& now) :
-  d_authzonequeries(0), d_outqueries(0), d_tcpoutqueries(0), d_dotoutqueries(0), d_throttledqueries(0), d_timeouts(0), d_unreachables(0), d_totUsec(0), d_now(now), d_cacheonly(false), d_doDNSSEC(false), d_doEDNS0(false), d_qNameMinimization(s_qnameminimization), d_lm(s_lm)
+  d_authzonequeries(0), d_outqueries(0), d_tcpoutqueries(0), d_dotoutqueries(0), d_throttledqueries(0), d_timeouts(0), d_unreachables(0), d_totUsec(0), d_fixednow(now), d_now(now), d_cacheonly(false), d_doDNSSEC(false), d_doEDNS0(false), d_qNameMinimization(s_qnameminimization), d_lm(s_lm)
+
 {
 }
 
@@ -1042,8 +1044,7 @@ bool SyncRes::isForwardOrAuth(const DNSName& qname) const
   return iter != t_sstorage.domainmap->end();
 }
 
-// Will be needed in the future
-static const char* timestamp(const struct timeval& tv, char* buf, size_t sz)
+const char* timestamp(const struct timeval& tv, char* buf, size_t sz)
 {
   const std::string s_timestampFormat = "%Y-%m-%dT%T";
   struct tm tm;

diff --git a/pdns/recursordist/syncres.hh b/pdns/recursordist/syncres.hh
index 50af5bf25ba02d755c39130710435fee10e8c878..ef6e27db568b364b333fd624a1cdbc4d3fc2ffc8 100644 (file)
--- a/pdns/recursordist/syncres.hh
+++ b/pdns/recursordist/syncres.hh
@@ -568,6 +568,7 @@ public:
   unsigned int d_timeouts;
   unsigned int d_unreachables;
   unsigned int d_totUsec;
+  const struct timeval d_fixednow;
 
 private:
   ComboAddress d_requestor;