Log port of requestor when doing extra logging.

CHANGELOG

@@ -40,6 +40,16 @@ 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.
+
+	    Add --min-cache-ttl option. I've resisted this for a long 
+	    time, on the grounds that disbelieving TTLs is never a 
+	    good idea, but I've been persuaded that there are 
+	    sometimes reasons to do it. (Step forward, GFW).
+	    To avoid misuse, there's a hard limit on the TTL 
+	    floor of one hour. Thansk to RinSatsuki for the patch.
+	
 	
 version 2.72
             Add ra-advrouter mode, for RFC-3775 mobile IPv6 support.

man/dnsmasq.8

@@ -81,6 +81,12 @@ the upstream DNS servers.
 .B --max-cache-ttl=<time>
 Set a maximum TTL value for entries in the cache.
 .TP
+.B --min-cache-ttl=<time>
+Extend short TTL values to the time given when caching them. Note that
+artificially extending TTL values is in general a bad idea, do not do it 
+unless you have a good reason, and understand what you are doing. 
+Dnsmasq limits the value of this option to one hour, unless recompiled.
+.TP
 .B --auth-ttl=<time>
 Set the TTL value returned in answers from the authoritative server.
 .TP
@@ -98,7 +104,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

src/cache.c

@@ -461,9 +461,11 @@ struct crec *cache_insert(char *name, struct all_addr *addr,
   if (flags & (F_IPV4 | F_IPV6 | F_CNAME))
     {
       log_query(flags | F_UPSTREAM, name, addr, NULL);
-      /* Don;t mess with TTL for DNSSEC records. */
+      /* Don't mess with TTL for DNSSEC records. */
       if (daemon->max_cache_ttl != 0 && daemon->max_cache_ttl < ttl)
 	ttl = daemon->max_cache_ttl;
+      if (daemon->min_cache_ttl != 0 && daemon->min_cache_ttl > ttl)
+	ttl = daemon->min_cache_ttl;
     }
 
   /* if previous insertion failed give up now. */
@@ -1638,7 +1640,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))
+    {
+      int port = prettyprint_addr(daemon->log_source_addr, daemon->addrbuff2);
+      if (flags & F_NOEXTRA)
+	my_syslog(LOG_INFO, "* %s/%u %s %s %s %s", daemon->addrbuff2, port, source, name, verb, dest);
+      else
+	my_syslog(LOG_INFO, "%u %s/%u %s %s %s %s", daemon->log_display_id, daemon->addrbuff2, port, source, name, verb, dest);
+    }
+  else
+    my_syslog(LOG_INFO, "%s %s %s %s", source, name, verb, dest);
 }
 
  

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 */
@@ -26,6 +27,7 @@
 #define RANDOM_SOCKS 64 /* max simultaneous random ports */
 #define LEASE_RETRY 60 /* on error, retry writing leasefile after LEASE_RETRY seconds */
 #define CACHESIZ 150 /* default cache size */
+#define TTL_FLOOR_LIMIT 3600 /* don't allow --min-cache-ttl to raise TTL above this under any circumstances */
 #define MAXLEASES 1000 /* maximum number of DHCP leases */
 #define PING_WAIT 3 /* wait for ping address-in-use test */
 #define PING_CACHE_TIME 30 /* Ping test assumed to be valid this long. */

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

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 
@@ -941,7 +943,7 @@ extern struct daemon {
   int max_logs;  /* queue limit */
   int cachesize, ftabsize;
   int port, query_port, min_port;
-  unsigned long local_ttl, neg_ttl, max_ttl, max_cache_ttl, auth_ttl;
+  unsigned long local_ttl, neg_ttl, max_ttl, min_cache_ttl, max_cache_ttl, auth_ttl;
   struct hostsfile *addn_hosts;
   struct dhcp_context *dhcp, *dhcp6;
   struct ra_interface *ra_interfaces;
@@ -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;
 

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);

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 */

src/option.c

@@ -148,6 +148,8 @@ struct myoption {
 #define LOPT_DNSSEC_TIME   336
 #define LOPT_LOOP_DETECT   337
 #define LOPT_IGNORE_ADDR   338
+#define LOPT_MINCTTL       339
+
 
 #ifdef HAVE_GETOPT_LONG
 static const struct option opts[] =  
@@ -160,7 +162,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' },
@@ -255,6 +257,7 @@ static const struct myoption opts[] =
     { "dhcp-broadcast", 2, 0, LOPT_BROADCAST },
     { "neg-ttl", 1, 0, LOPT_NEGTTL },
     { "max-ttl", 1, 0, LOPT_MAXTTL },
+    { "min-cache-ttl", 1, 0, LOPT_MINCTTL },
     { "max-cache-ttl", 1, 0, LOPT_MAXCTTL },
     { "dhcp-alternate-port", 2, 0, LOPT_ALTPORT },
     { "dhcp-scriptuser", 1, 0, LOPT_SCRIPTUSR },
@@ -357,7 +360,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 }, 
@@ -370,6 +373,8 @@ static struct {
   { 'T', ARG_ONE, "<integer>", gettext_noop("Specify time-to-live in seconds for replies from /etc/hosts."), NULL },
   { LOPT_NEGTTL, ARG_ONE, "<integer>", gettext_noop("Specify time-to-live in seconds for negative caching."), NULL },
   { LOPT_MAXTTL, ARG_ONE, "<integer>", gettext_noop("Specify time-to-live in seconds for maximum TTL to send to clients."), NULL },
+  { LOPT_MAXCTTL, ARG_ONE, "<integer>", gettext_noop("Specify time-to-live ceiling for cache."), NULL },
+  { LOPT_MINCTTL, ARG_ONE, "<integer>", gettext_noop("Specify time-to-live floor for cache."), NULL },
   { 'u', ARG_ONE, "<username>", gettext_noop("Change to this user after startup. (defaults to %s)."), CHUSER }, 
   { 'U', ARG_DUP, "set:<tag>,<class>", gettext_noop("Map DHCP vendor class to tag."), NULL },
   { 'v', 0, NULL, gettext_noop("Display dnsmasq version and copyright information."), NULL },
@@ -2421,6 +2426,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))
@@ -2450,6 +2461,7 @@ static int one_opt(int option, char *arg, char *errstr, char *gen_err, int comma
     case 'T':         /* --local-ttl */
     case LOPT_NEGTTL: /* --neg-ttl */
     case LOPT_MAXTTL: /* --max-ttl */
+    case LOPT_MINCTTL: /* --min-cache-ttl */
     case LOPT_MAXCTTL: /* --max-cache-ttl */
     case LOPT_AUTHTTL: /* --auth-ttl */
       {
@@ -2460,6 +2472,12 @@ static int one_opt(int option, char *arg, char *errstr, char *gen_err, int comma
 	  daemon->neg_ttl = (unsigned long)ttl;
 	else if (option == LOPT_MAXTTL)
 	  daemon->max_ttl = (unsigned long)ttl;
+	else if (option == LOPT_MINCTTL)
+	  {
+	    if (ttl > TTL_FLOOR_LIMIT)
+	      ttl = TTL_FLOOR_LIMIT;
+	    daemon->min_cache_ttl = (unsigned long)ttl;
+	  }
 	else if (option == LOPT_MAXCTTL)
 	  daemon->max_cache_ttl = (unsigned long)ttl;
 	else if (option == LOPT_AUTHTTL)