Add --log-queries=extra option for more complete logging.

9 files changed, 72 insertions, 17 deletions

diff --git a/CHANGELOG b/CHANGELOG
index e8bf80f..0bbb783 100644
--- a/CHANGELOG
+++ b/CHANGELOG
@@ -40,6 +40,9 @@ version 2.73
 	    nameservers in the unsigned parts of the DNS tree 
 	    which don't respond well to DNSSEC queries.
 
+	    Add --log-queries=extra option, which makes logs easier
+	    to search automatically.
+
 	
 version 2.72
             Add ra-advrouter mode, for RFC-3775 mobile IPv6 support.
diff --git a/man/dnsmasq.8 b/man/dnsmasq.8
index 4236ba3..227d74b 100644
--- a/man/dnsmasq.8
+++ b/man/dnsmasq.8
@@ -98,7 +98,10 @@ only, to stop dnsmasq daemonising in production, use
 .B -k.
 .TP
 .B \-q, --log-queries
-Log the results of DNS queries handled by dnsmasq. Enable a full cache dump on receipt of SIGUSR1.
+Log the results of DNS queries handled by dnsmasq. Enable a full cache dump on receipt of SIGUSR1. If the argument "extra" is supplied, ie
+.B --log-queries=extra
+then the log has extra information at the start of each line.
+This consists of a serial number which ties together the log lines associated with an individual query, and the IP address of the requestor.
 .TP
 .B \-8, --log-facility=<facility>
 Set the facility to which dnsmasq will send syslog entries, this
diff --git a/src/cache.c b/src/cache.c
index ff1ca6f..960bb79 100644
--- a/src/cache.c
+++ b/src/cache.c
@@ -1638,7 +1638,16 @@ void log_query(unsigned int flags, char *name, struct all_addr *addr, char *arg)
   if (strlen(name) == 0)
     name = ".";
 
-  my_syslog(LOG_INFO, "%s %s %s %s", source, name, verb, dest);
+  if (option_bool(OPT_EXTRALOG))
+    {
+      prettyprint_addr(daemon->log_source_addr, daemon->addrbuff2);
+      if (flags & F_NOEXTRA)
+	my_syslog(LOG_INFO, "* %s %s %s %s %s", daemon->addrbuff2, source, name, verb, dest);
+      else
+	my_syslog(LOG_INFO, "%u %s %s %s %s %s", daemon->log_display_id, daemon->addrbuff2, source, name, verb, dest);
+    }
+  else
+    my_syslog(LOG_INFO, "%s %s %s %s", source, name, verb, dest);
 }
 
  
diff --git a/src/config.h b/src/config.h
index 145820a..3b88d81 100644
--- a/src/config.h
+++ b/src/config.h
@@ -17,6 +17,7 @@
 #define FTABSIZ 150 /* max number of outstanding requests (default) */
 #define MAX_PROCS 20 /* max no children for TCP requests */
 #define CHILD_LIFETIME 150 /* secs 'till terminated (RFC1035 suggests > 120s) */
+#define TCP_MAX_QUERIES 100 /* Maximum number of queries per incoming TCP connection */
 #define EDNS_PKTSZ 4096 /* default max EDNS.0 UDP packet from RFC5625 */
 #define KEYBLOCK_LEN 40 /* choose to mininise fragmentation when storing DNSSEC keys */
 #define DNSSEC_WORK 50 /* Max number of queries to validate one question */
diff --git a/src/dnsmasq.c b/src/dnsmasq.c
index 5c7750d..c0c0589 100644
--- a/src/dnsmasq.c
+++ b/src/dnsmasq.c
@@ -93,6 +93,8 @@ int main (int argc, char **argv)
   daemon->packet = safe_malloc(daemon->packet_buff_sz);
   
   daemon->addrbuff = safe_malloc(ADDRSTRLEN);
+  if (option_bool(OPT_EXTRALOG))
+    daemon->addrbuff2 = safe_malloc(ADDRSTRLEN);
   
 #ifdef HAVE_DNSSEC
   if (option_bool(OPT_DNSSEC_VALID))
@@ -1587,6 +1589,9 @@ static void check_dns_listeners(fd_set *set, time_t now)
 		      }
 		}
 	      close(confd);
+
+	      /* The child can use up to TCP_MAX_QUERIES ids, so skip that many. */
+	      daemon->log_id += TCP_MAX_QUERIES;
 	    }
 #endif
 	  else
diff --git a/src/dnsmasq.h b/src/dnsmasq.h
index 2f45972..4e9aea4 100644
--- a/src/dnsmasq.h
+++ b/src/dnsmasq.h
@@ -238,7 +238,8 @@ struct event_desc {
 #define OPT_DNSSEC_NO_SIGN 48 
 #define OPT_LOCAL_SERVICE  49
 #define OPT_LOOP_DETECT    50
-#define OPT_LAST           51
+#define OPT_EXTRALOG       51
+#define OPT_LAST           52
 
 /* extra flags for my_syslog, we use a couple of facilities since they are known 
    not to occupy the same bits as priorities, no matter how syslog.h is set up. */
@@ -442,6 +443,7 @@ struct crec {
 #define F_NO_RR     (1u<<25)
 #define F_IPSET     (1u<<26)
 #define F_NSIGMATCH (1u<<27)
+#define F_NOEXTRA   (1u<<28)
 
 /* Values of uid in crecs with F_CONFIG bit set. */
 #define SRC_INTERFACE 0
@@ -599,7 +601,7 @@ struct frec {
 #endif
   unsigned int iface;
   unsigned short orig_id, new_id;
-  int fd, forwardall, flags;
+  int log_id, fd, forwardall, flags;
   time_t time;
   unsigned char *hash[HASH_SIZE];
 #ifdef HAVE_DNSSEC 
@@ -1002,6 +1004,8 @@ extern struct daemon {
   struct randfd randomsocks[RANDOM_SOCKS];
   int v6pktinfo; 
   struct addrlist *interface_addrs; /* list of all addresses/prefix lengths associated with all local interfaces */
+  int log_id, log_display_id; /* ids of transactions for logging */
+  union mysockaddr *log_source_addr;
 
   /* DHCP state */
   int dhcpfd, helperfd, pxefd; 
@@ -1033,6 +1037,7 @@ extern struct daemon {
 
   /* utility string buffer, hold max sized IP address as string */
   char *addrbuff;
+  char *addrbuff2; /* only allocated when OPT_EXTRALOG */
 
 } *daemon;
 
diff --git a/src/dnssec.c b/src/dnssec.c
index 8f27677..afb3dca 100644
--- a/src/dnssec.c
+++ b/src/dnssec.c
@@ -1038,7 +1038,7 @@ int dnssec_validate_by_ds(time_t now, struct dns_header *header, size_t plen, ch
 		      else
 			{
 			  a.addr.keytag = keytag;
-			  log_query(F_KEYTAG | F_UPSTREAM, name, &a, "DNSKEY keytag %u");
+			  log_query(F_NOEXTRA | F_KEYTAG | F_UPSTREAM, name, &a, "DNSKEY keytag %u");
 			  
 			  recp1->addr.key.keylen = rdlen - 4;
 			  recp1->addr.key.keydata = key;
@@ -1092,7 +1092,7 @@ int dnssec_validate_by_ds(time_t now, struct dns_header *header, size_t plen, ch
       return STAT_SECURE;
     }
 
-  log_query(F_UPSTREAM, name, NULL, "BOGUS DNSKEY");
+  log_query(F_NOEXTRA | F_UPSTREAM, name, NULL, "BOGUS DNSKEY");
   return STAT_BOGUS;
 }
 
@@ -1136,7 +1136,7 @@ int dnssec_validate_ds(time_t now, struct dns_header *header, size_t plen, char
   
   if (val == STAT_BOGUS)
     {
-      log_query(F_UPSTREAM, name, NULL, "BOGUS DS");
+      log_query(F_NOEXTRA | F_UPSTREAM, name, NULL, "BOGUS DS");
       return STAT_BOGUS;
     }
 
@@ -1201,7 +1201,7 @@ int dnssec_validate_ds(time_t now, struct dns_header *header, size_t plen, char
 	  
 	  cache_end_insert();  
 	  
-	  log_query(F_UPSTREAM, name, NULL, nons ? "no delegation" : "no DS");
+	  log_query(F_NOEXTRA | F_UPSTREAM, name, NULL, nons ? "no delegation" : "no DS");
 	}
 
       return nons ? STAT_NO_NS : STAT_NO_DS; 
@@ -1885,7 +1885,7 @@ int dnssec_validate_reply(time_t now, struct dns_header *header, size_t plen, ch
 			      else
 				{
 				  a.addr.keytag = keytag;
-				  log_query(F_KEYTAG | F_UPSTREAM, name, &a, "DS keytag %u");
+				  log_query(F_NOEXTRA | F_KEYTAG | F_UPSTREAM, name, &a, "DS keytag %u");
 				  crecp->addr.ds.digest = digest;
 				  crecp->addr.ds.keydata = key;
 				  crecp->addr.ds.algo = algo;
@@ -2058,10 +2058,10 @@ size_t dnssec_generate_query(struct dns_header *header, char *end, char *name, i
   char *types = querystr("dnssec-query", type);
 
   if (addr->sa.sa_family == AF_INET) 
-    log_query(F_DNSSEC | F_IPV4, name, (struct all_addr *)&addr->in.sin_addr, types);
+    log_query(F_NOEXTRA | F_DNSSEC | F_IPV4, name, (struct all_addr *)&addr->in.sin_addr, types);
 #ifdef HAVE_IPV6
   else
-    log_query(F_DNSSEC | F_IPV6, name, (struct all_addr *)&addr->in6.sin6_addr, types);
+    log_query(F_NOEXTRA | F_DNSSEC | F_IPV6, name, (struct all_addr *)&addr->in6.sin6_addr, types);
 #endif
   
   header->qdcount = htons(1);
diff --git a/src/forward.c b/src/forward.c
index 55f5833..713a64c 100644
--- a/src/forward.c
+++ b/src/forward.c
@@ -279,10 +279,10 @@ static int forward_query(int udpfd, union mysockaddr *udpaddr,
 	  plen = forward->stash_len;
 	  
 	  if (forward->sentto->addr.sa.sa_family == AF_INET) 
-	    log_query(F_DNSSEC | F_IPV4, "retry", (struct all_addr *)&forward->sentto->addr.in.sin_addr, "dnssec");
+	    log_query(F_NOEXTRA | F_DNSSEC | F_IPV4, "retry", (struct all_addr *)&forward->sentto->addr.in.sin_addr, "dnssec");
 #ifdef HAVE_IPV6
 	  else
-	    log_query(F_DNSSEC | F_IPV6, "retry", (struct all_addr *)&forward->sentto->addr.in6.sin6_addr, "dnssec");
+	    log_query(F_NOEXTRA | F_DNSSEC | F_IPV6, "retry", (struct all_addr *)&forward->sentto->addr.in6.sin6_addr, "dnssec");
 #endif
   
 	  if (forward->sentto->sfd)
@@ -389,6 +389,9 @@ static int forward_query(int udpfd, union mysockaddr *udpaddr,
       struct server *firstsentto = start;
       int forwarded = 0;
       
+      /* If a query is retried, use the log_id for the retry when logging the answer. */
+      forward->log_id = daemon->log_id;
+      
       if (option_bool(OPT_ADD_MAC))
 	plen = add_mac(header, plen, ((char *) header) + daemon->packet_buff_sz, &forward->source);
       
@@ -725,6 +728,11 @@ void reply_query(int fd, int family, time_t now)
   if (!(forward = lookup_frec(ntohs(header->id), hash)))
     return;
   
+  /* log_query gets called indirectly all over the place, so 
+     pass these in global variables - sorry. */
+  daemon->log_display_id = forward->log_id;
+  daemon->log_source_addr = &forward->source;
+  
   if (daemon->ignore_addr && RCODE(header) == NOERROR &&
       check_for_ignored_address(header, n, daemon->ignore_addr))
     return;
@@ -1258,6 +1266,11 @@ void receive_query(struct listener *listen, time_t now)
 	    dst_addr_4.s_addr = 0;
 	}
     }
+   
+  /* log_query gets called indirectly all over the place, so 
+     pass these in global variables - sorry. */
+  daemon->log_display_id = ++daemon->log_id;
+  daemon->log_source_addr = &source_addr;
   
   if (extract_request(header, (size_t)n, daemon->namebuff, &type))
     {
@@ -1675,7 +1688,8 @@ unsigned char *tcp_request(int confd, time_t now,
   struct in_addr dst_addr_4;
   union mysockaddr peer_addr;
   socklen_t peer_len = sizeof(union mysockaddr);
-  
+  int query_count = 0;
+
   if (getpeername(confd, (struct sockaddr *)&peer_addr, &peer_len) == -1)
     return packet;
   
@@ -1712,7 +1726,8 @@ unsigned char *tcp_request(int confd, time_t now,
 
   while (1)
     {
-      if (!packet ||
+      if (query_count == TCP_MAX_QUERIES ||
+	  !packet ||
 	  !read_write(confd, &c1, 1, 1) || !read_write(confd, &c2, 1, 1) ||
 	  !(size = c1 << 8 | c2) ||
 	  !read_write(confd, payload, size, 1))
@@ -1721,6 +1736,13 @@ unsigned char *tcp_request(int confd, time_t now,
       if (size < (int)sizeof(struct dns_header))
 	continue;
       
+      query_count++;
+
+      /* log_query gets called indirectly all over the place, so 
+	 pass these in global variables - sorry. */
+      daemon->log_display_id = ++daemon->log_id;
+      daemon->log_source_addr = &peer_addr;
+      
       check_subnet = 0;
 
       /* save state of "cd" flag in query */
diff --git a/src/option.c b/src/option.c
index 907d0cf..b7372be 100644
--- a/src/option.c
+++ b/src/option.c
@@ -149,6 +149,7 @@ struct myoption {
 #define LOPT_LOOP_DETECT   337
 #define LOPT_IGNORE_ADDR   338
 
+
 #ifdef HAVE_GETOPT_LONG
 static const struct option opts[] =  
 #else
@@ -160,7 +161,7 @@ static const struct myoption opts[] =
     { "no-poll", 0, 0, 'n' },
     { "help", 0, 0, 'w' },
     { "no-daemon", 0, 0, 'd' },
-    { "log-queries", 0, 0, 'q' },
+    { "log-queries", 2, 0, 'q' },
     { "user", 2, 0, 'u' },
     { "group", 2, 0, 'g' },
     { "resolv-file", 2, 0, 'r' },
@@ -357,7 +358,7 @@ static struct {
   { LOPT_FORCE, ARG_DUP, "<optspec>", gettext_noop("DHCP option sent even if the client does not request it."), NULL},
   { 'p', ARG_ONE, "<integer>", gettext_noop("Specify port to listen for DNS requests on (defaults to 53)."), NULL },
   { 'P', ARG_ONE, "<integer>", gettext_noop("Maximum supported UDP packet size for EDNS.0 (defaults to %s)."), "*" },
-  { 'q', OPT_LOG, NULL, gettext_noop("Log DNS queries."), NULL },
+  { 'q', ARG_DUP, NULL, gettext_noop("Log DNS queries."), NULL },
   { 'Q', ARG_ONE, "<integer>", gettext_noop("Force the originating port for upstream DNS queries."), NULL },
   { 'R', OPT_NO_RESOLV, NULL, gettext_noop("Do NOT read resolv.conf."), NULL },
   { 'r', ARG_DUP, "<path>", gettext_noop("Specify path to resolv.conf (defaults to %s)."), RESOLVFILE }, 
@@ -2421,6 +2422,12 @@ static int one_opt(int option, char *arg, char *errstr, char *gen_err, int comma
 	ret_err(gen_err);
       break;  
     
+    case 'q': /* --log-queries */
+      set_option_bool(OPT_LOG);
+      if (arg && strcmp(arg, "extra") == 0)
+	set_option_bool(OPT_EXTRALOG);
+      break;
+
     case LOPT_MAX_LOGS:  /* --log-async */
       daemon->max_logs = LOG_MAX; /* default */
       if (arg && !atoi_check(arg, &daemon->max_logs))