From 2c9119cd208445b35ea9cbf411ff4d508fef72bd Mon Sep 17 00:00:00 2001
From: bert hubert <bert.hubert@netherlabs.nl>
Date: Fri, 29 Sep 2017 22:37:49 +0200
Subject: [PATCH] Improve --quiet=false output for recursor to include DNSSEC
 and more timing details With this PR, pdns_recursor non-quiet logging shows
 DNSSEC status and adds time spent waiting for network, plus total time spent
 before answer was sent. This quantifies the internal overhead.

---
 pdns/pdns_recursor.cc | 15 +++++++++++----
 1 file changed, 11 insertions(+), 4 deletions(-)

diff --git a/pdns/pdns_recursor.cc b/pdns/pdns_recursor.cc
index 9be6586872..1875668f0b 100644
--- a/pdns/pdns_recursor.cc
+++ b/pdns/pdns_recursor.cc
@@ -1222,16 +1222,23 @@ static void startDoResolve(void *p)
         }
       }
     }
-
+    float spent=makeFloat(sr.getNow()-dc->d_now);
     if(!g_quiet) {
       L<<Logger::Error<<t_id<<" ["<<MT->getTid()<<"/"<<MT->numProcesses()<<"] answer to "<<(dc->d_mdp.d_header.rd?"":"non-rd ")<<"question '"<<dc->d_mdp.d_qname<<"|"<<DNSRecordContent::NumberToType(dc->d_mdp.d_qtype);
       L<<"': "<<ntohs(pw.getHeader()->ancount)<<" answers, "<<ntohs(pw.getHeader()->arcount)<<" additional, took "<<sr.d_outqueries<<" packets, "<<
-	sr.d_totUsec/1000.0<<" ms, "<<
-	sr.d_throttledqueries<<" throttled, "<<sr.d_timeouts<<" timeouts, "<<sr.d_tcpoutqueries<<" tcp connections, rcode="<<res<<endl;
+	sr.d_totUsec/1000.0<<" netw ms, "<< spent*1000.0<<" tot ms, "<<
+	sr.d_throttledqueries<<" throttled, "<<sr.d_timeouts<<" timeouts, "<<sr.d_tcpoutqueries<<" tcp connections, rcode="<< res;
+
+      if(!shouldNotValidate && sr.isDNSSECValidationRequested()) {
+	L<< ", dnssec="<<vStates[sr.getValidationState()];
+      }
+	
+      L<<endl;
+
     }
 
     sr.d_outqueries ? t_RC->cacheMisses++ : t_RC->cacheHits++;
-    float spent=makeFloat(sr.getNow()-dc->d_now);
+
     if(spent < 0.001)
       g_stats.answers0_1++;
     else if(spent < 0.010)
-- 
2.47.2