Add protobuf fields for the query's time in the response

This way it's possible to compute the latency by looking only
at the response message.
Implemented for:
* dnsdist
* dnspcap2protobuf
* ProtobufLogger.py
* rec

diff --git a/contrib/ProtobufLogger.py b/contrib/ProtobufLogger.py
index eaddd5cc56dd0e7b0a7017aebaf1c3a0f473553a..0983e1d437ac40318ef1c6e41cb4b31747921316 100644 (file)
--- a/contrib/ProtobufLogger.py
+++ b/contrib/ProtobufLogger.py
@@ -70,6 +70,13 @@ class PDNSPBConnHandler(object):
     def printResponse(self, message):
         if message.HasField('response'):
             response = message.response
+
+            if response.HasField('queryTimeSec'):
+                datestr = datetime.datetime.fromtimestamp(response.queryTimeSec).strftime('%Y-%m-%d %H:%M:%S')
+                if response.HasField('queryTimeUsec'):
+                    datestr = datestr + '.' + str(response.queryTimeUsec)
+                print("- Query time: %s" % (datestr))
+
             policystr = ''
             if response.HasField('appliedPolicy') and response.appliedPolicy:
                 policystr = ', Applied policy: ' + response.appliedPolicy

diff --git a/pdns/dnsdist-protobuf.cc b/pdns/dnsdist-protobuf.cc
index 12b9463f3ac07317a857238d84e42ce5070f869f..7aec30c6c6a2e2bddf2438900ea7825a87963d8c 100644 (file)
--- a/pdns/dnsdist-protobuf.cc
+++ b/pdns/dnsdist-protobuf.cc
@@ -21,4 +21,11 @@ DNSDistProtoBufMessage::DNSDistProtoBufMessage(DNSProtoBufMessageType type, cons
   }
 };
 
+DNSDistProtoBufMessage::DNSDistProtoBufMessage(const DNSResponse& dr): DNSProtoBufMessage(Response, dr.uniqueId, dr.remote, dr.local, *dr.qname, dr.qtype, dr.qclass, dr.dh->id, dr.tcp, dr.len)
+{
+  setQueryTime(dr.queryTime->tv_sec, dr.queryTime->tv_nsec / 1000);
+  setResponseCode(dr.dh->rcode);
+  addRRsFromPacket((const char*) dr.dh, dr.len);
+};
+
 #endif /* HAVE_PROTOBUF */

diff --git a/pdns/dnsdist-protobuf.hh b/pdns/dnsdist-protobuf.hh
index 222b6616d43c10f7b58f65a472829614c54080ad..eb09c0805f91e333d30917d5deaedaa108c0c992 100644 (file)
--- a/pdns/dnsdist-protobuf.hh
+++ b/pdns/dnsdist-protobuf.hh
@@ -6,4 +6,5 @@ class DNSDistProtoBufMessage: public DNSProtoBufMessage
 {
 public:
   DNSDistProtoBufMessage(DNSProtoBufMessageType type, const DNSQuestion& dq);
+  DNSDistProtoBufMessage(const DNSResponse& dr);
 };

diff --git a/pdns/dnsdist-tcp.cc b/pdns/dnsdist-tcp.cc
index 254dc16b159ec1772ead39d127d0bdd4a83a756c..35c96d67129a6ef8dc4837f3fd61cfb2afde6fb7 100644 (file)
--- a/pdns/dnsdist-tcp.cc
+++ b/pdns/dnsdist-tcp.cc
@@ -267,7 +267,7 @@ void* tcpClientThread(int pipefd)
        string poolname;
        int delayMsec=0;
        struct timespec now;
-       gettime(&now);
+       gettime(&now, true);
 
        if (!processQuery(localDynBlockNMG, localDynBlockSMT, localRulactions, blockFilter, dq, poolname, &delayMsec, now)) {
          goto drop;
@@ -431,7 +431,7 @@ void* tcpClientThread(int pipefd)
         }
 
         dh = (struct dnsheader*) response;
-        DNSQuestion dr(&qname, qtype, qclass, &ci.cs->local, &ci.remote, dh, responseSize, responseLen, true);
+        DNSResponse dr(&qname, qtype, qclass, &ci.cs->local, &ci.remote, dh, responseSize, responseLen, true, &now);
 #ifdef HAVE_PROTOBUF
         dr.uniqueId = dq.uniqueId;
 #endif

diff --git a/pdns/dnsdist.cc b/pdns/dnsdist.cc
index f4504de5c5b7b5eea027e1060053f9360e455b5b..a0a550dca19cd52c4818f7c46ebdae2969d7a7cd 100644 (file)
--- a/pdns/dnsdist.cc
+++ b/pdns/dnsdist.cc
@@ -400,7 +400,7 @@ void* responderThread(std::shared_ptr<DownstreamState> state)
     dh->id = ids->origID;
 
     uint16_t addRoom = 0;
-    DNSQuestion dr(&ids->qname, ids->qtype, ids->qclass, &ids->origDest, &ids->origRemote, dh, sizeof(packet), responseLen, false);
+    DNSResponse dr(&ids->qname, ids->qtype, ids->qclass, &ids->origDest, &ids->origRemote, dh, sizeof(packet), responseLen, false, &ids->sentTime.d_start);
 #ifdef HAVE_PROTOBUF
     dr.uniqueId = ids->uniqueId;
 #endif
@@ -821,7 +821,7 @@ bool processQuery(LocalStateHolder<NetmaskTree<DynBlock> >& localDynNMGBlock,
   return true;
 }
 
-bool processResponse(LocalStateHolder<vector<pair<std::shared_ptr<DNSRule>, std::shared_ptr<DNSResponseAction> > > >& localRespRulactions, DNSQuestion& dr)
+bool processResponse(LocalStateHolder<vector<pair<std::shared_ptr<DNSRule>, std::shared_ptr<DNSResponseAction> > > >& localRespRulactions, DNSResponse& dr)
 {
   std::string ruleresult;
   for(const auto& lr : *localRespRulactions) {

diff --git a/pdns/dnsdist.hh b/pdns/dnsdist.hh
index 62ff9c3ecb6b3dc9ea0018d5eead27c3d00914c3..4ed5a1259986eba1cac43861099495cd9bb692c0 100644 (file)
--- a/pdns/dnsdist.hh
+++ b/pdns/dnsdist.hh
@@ -107,16 +107,21 @@ extern struct DNSDistStats g_stats;
 
 struct StopWatch
 {
+  StopWatch(bool realTime=false): d_needRealTime(realTime)
+  {
+  }
   struct timespec d_start{0,0};
+  bool d_needRealTime{false};
+
   void start() {  
-    if(gettime(&d_start) < 0)
+    if(gettime(&d_start, d_needRealTime) < 0)
       unixDie("Getting timestamp");
     
   }
   
   double udiff() const {
     struct timespec now;
-    if(gettime(&now) < 0)
+    if(gettime(&now, d_needRealTime) < 0)
       unixDie("Getting timestamp");
     
     return 1000000.0*(now.tv_sec - d_start.tv_sec) + (now.tv_nsec - d_start.tv_nsec)/1000.0;
@@ -124,7 +129,7 @@ struct StopWatch
 
   double udiffAndSet() {
     struct timespec now;
-    if(gettime(&now) < 0)
+    if(gettime(&now, d_needRealTime) < 0)
       unixDie("Getting timestamp");
     
     auto ret= 1000000.0*(now.tv_sec - d_start.tv_sec) + (now.tv_nsec - d_start.tv_nsec)/1000.0;
@@ -195,7 +200,7 @@ private:
 
 struct IDState
 {
-  IDState() : origFD(-1), delayMsec(0) { origDest.sin4.sin_family = 0;}
+  IDState() : origFD(-1), sentTime(true), delayMsec(0) { origDest.sin4.sin_family = 0;}
   IDState(const IDState& orig)
   {
     origFD = orig.origFD;
@@ -396,6 +401,13 @@ struct DNSQuestion
   bool skipCache{false};
 };
 
+struct DNSResponse : DNSQuestion
+{
+  DNSResponse(const DNSName* name, uint16_t type, uint16_t class_, const ComboAddress* lc, const ComboAddress* rem, struct dnsheader* header, size_t bufferSize, uint16_t queryLen, bool isTcp, const struct timespec* queryTime_): DNSQuestion(name, type, class_, lc, rem, header, bufferSize, queryLen, isTcp), queryTime(queryTime_) { }
+
+  const struct timespec* queryTime;
+};
+
 typedef std::function<bool(const DNSQuestion*)> blockfilter_t;
 template <class T> using NumberedVector = std::vector<std::pair<unsigned int, T> >;
 
@@ -437,7 +449,7 @@ class DNSResponseAction
 {
 public:
   enum class Action { None };
-  virtual Action operator()(DNSQuestion*, string* ruleresult) const =0;
+  virtual Action operator()(DNSResponse*, string* ruleresult) const =0;
   virtual string toString() const = 0;
 };
 
@@ -638,7 +650,7 @@ void resetLuaSideEffect(); // reset to indeterminate state
 bool responseContentMatches(const char* response, const uint16_t responseLen, const DNSName& qname, const uint16_t qtype, const uint16_t qclass, const ComboAddress& remote);
 bool processQuery(LocalStateHolder<NetmaskTree<DynBlock> >& localDynBlockNMG,
                   LocalStateHolder<SuffixMatchTree<DynBlock> >& localDynBlockSMT, LocalStateHolder<vector<pair<std::shared_ptr<DNSRule>, std::shared_ptr<DNSAction> > > >& localRulactions, blockfilter_t blockFilter, DNSQuestion& dq, string& poolname, int* delayMsec, const struct timespec& now);
-bool processResponse(LocalStateHolder<vector<pair<std::shared_ptr<DNSRule>, std::shared_ptr<DNSResponseAction> > > >& localRespRulactions, DNSQuestion& dq);
+bool processResponse(LocalStateHolder<vector<pair<std::shared_ptr<DNSRule>, std::shared_ptr<DNSResponseAction> > > >& localRespRulactions, DNSResponse& dr);
 bool fixUpResponse(char** response, uint16_t* responseLen, size_t* responseSize, const DNSName& qname, uint16_t origFlags, bool ednsAdded, bool ecsAdded, std::vector<uint8_t>& rewrittenResponse, uint16_t addRoom);
 void restoreFlags(struct dnsheader* dh, uint16_t origFlags);
 

diff --git a/pdns/dnsmessage.proto b/pdns/dnsmessage.proto
index 10c514c16b59a6f686d6b3524143c53183c2d5a0..f9457fe559038e46d84ab2a59b8f635b227c1a5b 100644 (file)
--- a/pdns/dnsmessage.proto
+++ b/pdns/dnsmessage.proto
@@ -43,6 +43,8 @@ message PBDNSMessage {
     repeated DNSRR rrs = 2;
     optional string appliedPolicy = 3;
     repeated string tags = 4;
+    optional uint32 queryTimeSec = 5;
+    optional uint32 queryTimeUsec = 6;
   }
 
   optional DNSResponse response = 13;

diff --git a/pdns/dnspcap2protobuf.cc b/pdns/dnspcap2protobuf.cc
index 87477847f49e7638b7608a4d67908a00cbaec0ec..73c6405c190fcb180fb2c4b8f6d66ba872818cbc 100644 (file)
--- a/pdns/dnspcap2protobuf.cc
+++ b/pdns/dnspcap2protobuf.cc
@@ -52,7 +52,7 @@ try {
   if(argc==4)
     ind=atoi(argv[3]);
 
-  std::map<uint16_t,boost::uuids::uuid> ids;
+  std::map<uint16_t,std::pair<boost::uuids::uuid,struct timeval> > ids;
   boost::uuids::random_generator uuidGenerator;
   try {
     while (pr.getUDPPacket()) {
@@ -77,14 +77,20 @@ try {
       }
 
       boost::uuids::uuid uniqueId;
+      struct timeval queryTime = { 0, 0 };
+      bool hasQueryTime = false;
       if (!dh->qr) {
+        queryTime.tv_sec = pr.d_pheader.ts.tv_sec;
+        queryTime.tv_usec = pr.d_pheader.ts.tv_usec;
         uniqueId = uuidGenerator();
-        ids[dh->id] = uniqueId;
+        ids[dh->id] = std::make_pair(uniqueId, queryTime);
       }
       else {
         const auto& it = ids.find(dh->id);
         if (it != ids.end()) {
-          uniqueId = it->second;
+          uniqueId = it->second.first;
+          queryTime = it->second.second;
+          hasQueryTime = true;
         }
         else {
           uniqueId = uuidGenerator();
@@ -101,6 +107,10 @@ try {
 
       if (dh->qr) {
         message.setResponseCode(dh->rcode);
+        if (hasQueryTime) {
+          message.setQueryTime(queryTime.tv_sec, queryTime.tv_usec);
+        }
+
         try {
           message.addRRsFromPacket((const char*) dh, pr.d_len);
         }

diff --git a/pdns/dnsrulactions.hh b/pdns/dnsrulactions.hh
index 33284d5f24e6956c480d0ef5f5a5fa7f038ff8ca..2d6f9d2abb32a090db425d58f1ec040536578196 100644 (file)
--- a/pdns/dnsrulactions.hh
+++ b/pdns/dnsrulactions.hh
@@ -934,10 +934,10 @@ public:
   RemoteLogResponseAction(std::shared_ptr<RemoteLogger> logger): d_logger(logger)
   {
   }
-  DNSResponseAction::Action operator()(DNSQuestion* dq, string* ruleresult) const override
+  DNSResponseAction::Action operator()(DNSResponse* dr, string* ruleresult) const override
   {
 #ifdef HAVE_PROTOBUF
-    DNSDistProtoBufMessage message(DNSDistProtoBufMessage::Response, *dq);
+    DNSDistProtoBufMessage message(*dr);
     std::string data;
     message.serialize(data);
     d_logger->queueData(data);

diff --git a/pdns/pdns_recursor.cc b/pdns/pdns_recursor.cc
index 5a549a2c144cb107fcb9c9087febf6f600abaf2f..95950c782450286371fddb663f7f071bff7af49b 100644 (file)
--- a/pdns/pdns_recursor.cc
+++ b/pdns/pdns_recursor.cc
@@ -985,6 +985,7 @@ void startDoResolve(void *p)
       pbMessage.setResponseCode(pw.getHeader()->rcode);
       pbMessage.setAppliedPolicy(appliedPolicy);
       pbMessage.setPolicyTags(dc->d_policyTags);
+      pbMessage.setQueryTime(dc->d_now.tv_sec, dc->d_now.tv_usec);
       protobufLogResponse(luaconfsLocal->protobufServer, pbMessage);
     }
 #endif
@@ -1383,6 +1384,7 @@ string* doProcessUDPQuestion(const std::string& question, const ComboAddress& fr
         const ComboAddress& requestor = requestorNM.getMaskedNetwork();
         pbMessage.update(uniqueId, &requestor, &destaddr, false, dh->id);
         pbMessage.setEDNSSubnet(ednssubnet);
+        pbMessage.setQueryTime(g_now.tv_sec, g_now.tv_usec);
         protobufLogResponse(luaconfsLocal->protobufServer, pbMessage);
       }
 #endif /* HAVE_PROTOBUF */

diff --git a/pdns/protobuf.cc b/pdns/protobuf.cc
index 304a88cb880e8c28896ec39e18c4539b44218654..248fd608defc8ac443bd9c782d675e89bc9fed8d 100644 (file)
--- a/pdns/protobuf.cc
+++ b/pdns/protobuf.cc
@@ -47,6 +47,17 @@ void DNSProtoBufMessage::setTime(time_t sec, uint32_t usec)
 #endif /* HAVE_PROTOBUF */
 }
 
+void DNSProtoBufMessage::setQueryTime(time_t sec, uint32_t usec)
+{
+#ifdef HAVE_PROTOBUF
+  PBDNSMessage_DNSResponse* response = d_message.mutable_response();
+  if (response) {
+    response->set_querytimesec(sec);
+    response->set_querytimeusec(usec);
+  }
+#endif /* HAVE_PROTOBUF */
+}
+
 void DNSProtoBufMessage::setEDNSSubnet(const Netmask& subnet)
 {
 #ifdef HAVE_PROTOBUF

diff --git a/pdns/protobuf.hh b/pdns/protobuf.hh
index faf70c27dba5ab5f5cdb58b01575fa352983926a..c1cd49e4dbe8940a369fa2dc22266e9500e0ed75 100644 (file)
--- a/pdns/protobuf.hh
+++ b/pdns/protobuf.hh
@@ -37,6 +37,7 @@ public:
   void setEDNSSubnet(const Netmask& subnet);
   void setBytes(size_t bytes);
   void setTime(time_t sec, uint32_t usec);
+  void setQueryTime(time_t sec, uint32_t usec);
   void setResponseCode(uint8_t rcode);
   void addRRsFromPacket(const char* packet, const size_t len);
   void serialize(std::string& data) const;