From: Remi Gacogne Date: Wed, 6 Jul 2016 16:54:39 +0000 (+0200) Subject: Add protobuf fields for the query's time in the response X-Git-Tag: rec-4.0.0~6^2 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=refs%2Fpull%2F4125%2Fhead;p=thirdparty%2Fpdns.git 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 eaddd5cc56..0983e1d437 100644 --- 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 12b9463f3a..7aec30c6c6 100644 --- 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 222b6616d4..eb09c0805f 100644 --- 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 254dc16b15..35c96d6712 100644 --- 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 f4504de5c5..a0a550dca1 100644 --- a/pdns/dnsdist.cc +++ b/pdns/dnsdist.cc @@ -400,7 +400,7 @@ void* responderThread(std::shared_ptr 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 >& localDynNMGBlock, return true; } -bool processResponse(LocalStateHolder, std::shared_ptr > > >& localRespRulactions, DNSQuestion& dr) +bool processResponse(LocalStateHolder, std::shared_ptr > > >& localRespRulactions, DNSResponse& dr) { std::string ruleresult; for(const auto& lr : *localRespRulactions) { diff --git a/pdns/dnsdist.hh b/pdns/dnsdist.hh index 62ff9c3ecb..4ed5a12599 100644 --- 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 blockfilter_t; template using NumberedVector = std::vector >; @@ -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 >& localDynBlockNMG, LocalStateHolder >& localDynBlockSMT, LocalStateHolder, std::shared_ptr > > >& localRulactions, blockfilter_t blockFilter, DNSQuestion& dq, string& poolname, int* delayMsec, const struct timespec& now); -bool processResponse(LocalStateHolder, std::shared_ptr > > >& localRespRulactions, DNSQuestion& dq); +bool processResponse(LocalStateHolder, std::shared_ptr > > >& 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& rewrittenResponse, uint16_t addRoom); void restoreFlags(struct dnsheader* dh, uint16_t origFlags); diff --git a/pdns/dnsmessage.proto b/pdns/dnsmessage.proto index 10c514c16b..f9457fe559 100644 --- 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 87477847f4..73c6405c19 100644 --- a/pdns/dnspcap2protobuf.cc +++ b/pdns/dnspcap2protobuf.cc @@ -52,7 +52,7 @@ try { if(argc==4) ind=atoi(argv[3]); - std::map ids; + std::map > 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 33284d5f24..2d6f9d2abb 100644 --- a/pdns/dnsrulactions.hh +++ b/pdns/dnsrulactions.hh @@ -934,10 +934,10 @@ public: RemoteLogResponseAction(std::shared_ptr 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 5a549a2c14..95950c7824 100644 --- 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 304a88cb88..248fd608de 100644 --- 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 faf70c27db..c1cd49e4db 100644 --- 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;