Log lengthy DNS lookups. Bug 514
authorJeremy Harris <jgh146exb@wizmail.org>
Thu, 7 May 2015 20:36:22 +0000 (21:36 +0100)
committerJeremy Harris <jgh146exb@wizmail.org>
Thu, 7 May 2015 20:36:22 +0000 (21:36 +0100)
    Original by <derrick.rice@gmail.com>, massaged by JH

13 files changed:
doc/doc-docbook/spec.xfpt
doc/doc-txt/NewStuff
src/src/globals.c
src/src/globals.h
src/src/host.c
src/src/readconf.c
test/confs/0606 [new file with mode: 0644]
test/dnszones-src/db.test.ex
test/runtest
test/scripts/0000-Basic/0606 [new file with mode: 0644]
test/src/fakens.c
test/stderr/0606 [new file with mode: 0644]
test/stdout/0606 [new file with mode: 0644]

index bc34d65..9baaad2 100644 (file)
@@ -13175,6 +13175,7 @@ listed in more than one group.
 .row &%message_logs%&                "create per-message logs"
 .row &%preserve_message_logs%&       "after message completion"
 .row &%process_log_path%&            "for SIGUSR1 and &'exiwhat'&"
+.row &%slow_lookup_log%&             "control logging of slow DNS lookups"
 .row &%syslog_duplication%&          "controls duplicate log lines on syslog"
 .row &%syslog_facility%&             "set syslog &""facility""& field"
 .row &%syslog_processname%&          "set syslog &""ident""& field"
@@ -14163,6 +14164,7 @@ take. I haven't found any documentation about timeouts on DNS lookups; these
 parameter values are available in the external resolver interface structure,
 but nowhere does it seem to describe how they are used or what you might want
 to set in them.
+See also the &%slow_lookup_log%& option.
 
 
 .option dns_retry main integer 0
@@ -15722,6 +15724,16 @@ it qualifies them only if the message came from a host that matches
 using TCP/IP), and the &%-bnq%& option was not set.
 
 
+.option slow_lookup_log main integer 0
+.cindex "logging" "slow lookups"
+.cindex "dns" "logging slow lookups"
+This option controls logging of slow lookups.
+If the value is nonzero it is taken as a number of milliseconds
+and lookups taking longer than this are logged.
+Currently this applies only to DNS lookups.
+
+
+
 .option smtp_accept_keepalive main boolean true
 .cindex "keepalive" "on incoming connection"
 This option controls the setting of the SO_KEEPALIVE option on incoming
index cac6f7c..aa60f46 100644 (file)
@@ -31,6 +31,8 @@ Version 4.86
  9. If built with EXPERIMENTAL_INTERNATIONAL, an expansion item for a commonly
     used encoding of Maildir folder names.
 
+10. A logging option for slow DNS lookups,
+
 
 Version 4.85
 ------------
index 868b27e..3cbbbd3 100644 (file)
@@ -1230,6 +1230,7 @@ uschar *sending_ip_address     = NULL;
 int     sending_port           = -1;
 SIGNAL_BOOL sigalrm_seen       = FALSE;
 uschar **sighup_argv           = NULL;
+int     slow_lookup_log        = 0;    /* millisecs, zero disables */
 int     smtp_accept_count      = 0;
 BOOL    smtp_accept_keepalive  = TRUE;
 int     smtp_accept_max        = 20;
index 8aa69bf..d90854c 100644 (file)
@@ -777,6 +777,7 @@ extern uschar *sending_ip_address;     /* Address of outgoing (SMTP) interface *
 extern int     sending_port;           /* Port of outgoing interface */
 extern SIGNAL_BOOL sigalrm_seen;       /* Flag for sigalrm_handler */
 extern uschar **sighup_argv;           /* Args for re-execing after SIGHUP */
+extern int     slow_lookup_log;        /* Log DNS lookups taking loger than N millisecs */
 extern int     smtp_accept_count;      /* Count of connections */
 extern BOOL    smtp_accept_keepalive;  /* Set keepalive on incoming */
 extern int     smtp_accept_max;        /* Max SMTP connections */
index 4d76fc4..45ec136 100644 (file)
@@ -94,6 +94,53 @@ random_seed = 1103515245 * random_seed + 12345;
 return (unsigned int)(random_seed >> 16) % limit;
 }
 
+/*************************************************
+*      Wrappers for logging lookup times         *
+*************************************************/
+
+/* When the 'slow_lookup_log' variable is enabled, these wrappers will
+write to the log file all (potential) dns lookups that take more than
+slow_lookup_log milliseconds
+*/
+
+static void
+log_long_lookup(const uschar * type, const uschar * data, unsigned long msec)
+{
+log_write(0, LOG_MAIN, "Long %s lookup for '%s': %lu msec",
+  type, data, msec);
+}
+
+
+/* returns the current system epoch time in milliseconds. */
+static unsigned long
+get_time_in_ms()
+{
+struct timeval tmp_time;
+unsigned long seconds, microseconds;
+
+gettimeofday(&tmp_time, NULL);
+seconds = (unsigned long) tmp_time.tv_sec;
+microseconds = (unsigned long) tmp_time.tv_usec;
+return seconds*1000 + microseconds/1000;
+}
+
+
+static int
+dns_lookup_timerwrap(dns_answer *dnsa, const uschar *name, int type,
+  const uschar **fully_qualified_name)
+{
+int retval;
+unsigned long time_msec;
+
+if (!slow_lookup_log)
+  return dns_lookup(dnsa, name, type, fully_qualified_name);
+
+time_msec = get_time_in_ms();
+retval = dns_lookup(dnsa, name, type, fully_qualified_name);
+if ((time_msec = get_time_in_ms() - time_msec) > slow_lookup_log)
+  log_long_lookup(US"name", name, time_msec);
+return retval;
+}
 
 
 /*************************************************
@@ -217,7 +264,7 @@ if (ipa != 0)
 else
   {
   int type = (af == AF_INET)? T_A:T_AAAA;
-  int rc = dns_lookup(&dnsa, lname, type, NULL);
+  int rc = dns_lookup_timerwrap(&dnsa, lname, type, NULL);
   int count = 0;
 
   lookup_dnssec_authenticated = NULL;
@@ -1454,6 +1501,9 @@ int len;
 uschar *s, *t;
 struct hostent *hosts;
 struct in_addr addr;
+unsigned long time_msec;
+
+if (slow_lookup_log) time_msec = get_time_in_ms();
 
 /* Lookup on IPv6 system */
 
@@ -1489,6 +1539,11 @@ addr.s_addr = (S_ADDR_TYPE)inet_addr(CS sender_host_address);
 hosts = gethostbyaddr(CS(&addr), sizeof(addr), AF_INET);
 #endif
 
+if (  slow_lookup_log
+   && (time_msec = get_time_in_ms() - time_msec) > slow_lookup_log
+   )
+  log_long_lookup(US"name", sender_host_address, time_msec);
+
 /* Failed to look up the host. */
 
 if (hosts == NULL)
@@ -1621,7 +1676,7 @@ while ((ordername = string_nextinlist(&list, &sep, buffer, sizeof(buffer)))
     {
     dns_init(FALSE, FALSE, FALSE);    /* dnssec ctrl by dns_dnssec_ok glbl */
     dns_build_reverse(sender_host_address, buffer);
-    rc = dns_lookup(&dnsa, buffer, T_PTR, NULL);
+    rc = dns_lookup_timerwrap(&dnsa, buffer, T_PTR, NULL);
 
     /* The first record we come across is used for the name; others are
     considered to be aliases. We have to scan twice, in order to find out the
@@ -1961,11 +2016,14 @@ for (i = 1; i <= times;
   BOOL ipv4_addr;
   int error_num = 0;
   struct hostent *hostdata;
+  unsigned long time_msec;
 
   #ifdef STAND_ALONE
   printf("Looking up: %s\n", host->name);
   #endif
 
+  if (slow_lookup_log) time_msec = get_time_in_ms();
+
   #if HAVE_IPV6
   if (running_in_test_harness)
     hostdata = host_fake_gethostbyname(host->name, af, &error_num);
@@ -1989,6 +2047,11 @@ for (i = 1; i <= times;
     }
   #endif   /* HAVE_IPV6 */
 
+  if (  slow_lookup_log
+     && (time_msec = get_time_in_ms() - time_msec) > slow_lookup_log
+        )
+       log_long_lookup(US"name", host->name, time_msec);
+
   if (hostdata == NULL)
     {
     uschar *error;
@@ -2263,7 +2326,7 @@ for (; i >= 0; i--)
   dns_answer dnsa;
   dns_scan dnss;
 
-  int rc = dns_lookup(&dnsa, host->name, type, fully_qualified_name);
+  int rc = dns_lookup_timerwrap(&dnsa, host->name, type, fully_qualified_name);
   lookup_dnssec_authenticated = !dnssec_request ? NULL
     : dns_is_secure(&dnsa) ? US"yes" : US"no";
 
@@ -2527,7 +2590,7 @@ if ((whichrrs & HOST_FIND_BY_SRV) != 0)
 
   dnssec = DS_UNK;
   lookup_dnssec_authenticated = NULL;
-  rc = dns_lookup(&dnsa, buffer, ind_type, CUSS &temp_fully_qualified_name);
+  rc = dns_lookup_timerwrap(&dnsa, buffer, ind_type, CUSS &temp_fully_qualified_name);
 
   if (dnssec_request)
     {
@@ -2573,7 +2636,7 @@ if (rc != DNS_SUCCEED && (whichrrs & HOST_FIND_BY_MX) != 0)
   ind_type = T_MX;
   dnssec = DS_UNK;
   lookup_dnssec_authenticated = NULL;
-  rc = dns_lookup(&dnsa, host->name, ind_type, fully_qualified_name);
+  rc = dns_lookup_timerwrap(&dnsa, host->name, ind_type, fully_qualified_name);
 
   if (dnssec_request)
     {
@@ -3079,9 +3142,6 @@ dns_init(FALSE, FALSE, FALSE);    /* clear the dnssec bit for getaddrbyname */
 return yield;
 }
 
-
-
-
 /*************************************************
 **************************************************
 *             Stand-alone test program           *
index 67241cb..dfede67 100644 (file)
@@ -373,6 +373,7 @@ static optionlist optionlist_config[] = {
   { "rfc1413_hosts",            opt_stringptr,   &rfc1413_hosts },
   { "rfc1413_query_timeout",    opt_time,        &rfc1413_query_timeout },
   { "sender_unqualified_hosts", opt_stringptr,   &sender_unqualified_hosts },
+  { "slow_lookup_log",          opt_int,         &slow_lookup_log },
   { "smtp_accept_keepalive",    opt_bool,        &smtp_accept_keepalive },
   { "smtp_accept_max",          opt_int,         &smtp_accept_max },
   { "smtp_accept_max_nonmail",  opt_int,         &smtp_accept_max_nonmail },
diff --git a/test/confs/0606 b/test/confs/0606
new file mode 100644 (file)
index 0000000..538e859
--- /dev/null
@@ -0,0 +1,24 @@
+# Exim test configuration 0606
+
+exim_path = EXIM_PATH
+host_lookup_order = bydns
+spool_directory = DIR/spool
+log_file_path = DIR/spool/log/SERVER%slog
+gecos_pattern = ""
+gecos_name = CALLER_NAME
+
+slow_lookup_log = 1000
+
+acl_smtp_rcpt = accept verify = recipient
+
+queue_only
+
+begin routers
+
+all:
+  driver = dnslookup
+  verify_only
+  self = send
+
+# End
+
index ab16434..1339981 100644 (file)
@@ -405,4 +405,10 @@ DNSSEC mxdane256ta MX  1  dane256ta.
 DNSSEC dane256ta   A       HOSTIPV4
 DNSSEC _1225._tcp.dane256ta TLSA  2 0 1 b2c6f27f2d16390b4f71cacc69742bf610d750534fab240516c0f2deb4042ad4
 
+; ------- Testing delays ------------
+
+DELAY=500  delay500  A HOSTIPV4
+DELAY=1500 delay1500 A HOSTIPV4
+
+
 ; End
index f215bf4..62ab01b 100755 (executable)
@@ -1367,6 +1367,9 @@ $munges =
     'scanfile_size' =>
     { 'stdout' => 's/(Content-length:) \d\d\d/$1 ddd/' },
 
+    'delay_1500' =>
+    { 'stderr' => 's/(1[5-9]|23\d)\d\d msec/ssss msec/' },
+
   };
 
 
diff --git a/test/scripts/0000-Basic/0606 b/test/scripts/0000-Basic/0606
new file mode 100644 (file)
index 0000000..6899784
--- /dev/null
@@ -0,0 +1,19 @@
+# dns log long lookups
+# Exim test configuration 0606
+#
+munge delay_1500
+#
+exim -bh 127.0.0.1
+helo test
+mail from:<ralph@dustyshoes.tld>
+rcpt to:<should_log@delay1500.test.ex>
+quit
+****
+#
+#
+exim -bh 127.0.0.1
+helo test
+mail from:<ralph@dustyshoes.tld>
+rcpt to:<should_not_log@delay500.test.ex>
+quit
+****
index baabf1d..1228c70 100644 (file)
@@ -50,6 +50,9 @@ line in the zone file contains exactly this:
 and the domain is not found. It converts the the result to PASS_ON instead of
 HOST_NOT_FOUND.
 
+Any DNS record line in a zone file can be prefixed with "DELAY=" and
+a number of milliseconds (followed by whitespace).
+
 Any DNS record line in a zone file can be prefixed with "DNSSEC" and
 at least one space; if all the records found by a lookup are marked
 as such then the response will have the "AD" bit set. */
@@ -63,6 +66,7 @@ as such then the response will have the "AD" bit set. */
 #include <errno.h>
 #include <arpa/nameser.h>
 #include <sys/types.h>
+#include <sys/time.h>
 #include <dirent.h>
 
 #define FALSE         0
@@ -224,6 +228,38 @@ return pk;
 
 
 
+/*************************************************/
+
+static void
+milliwait(struct itimerval *itval)
+{
+sigset_t sigmask;
+sigset_t old_sigmask;
+
+if (itval->it_value.tv_usec < 100 && itval->it_value.tv_sec == 0)
+  return;
+(void)sigemptyset(&sigmask);                           /* Empty mask */
+(void)sigaddset(&sigmask, SIGALRM);                    /* Add SIGALRM */
+(void)sigprocmask(SIG_BLOCK, &sigmask, &old_sigmask);  /* Block SIGALRM */
+(void)setitimer(ITIMER_REAL, itval, NULL);             /* Start timer */
+(void)sigfillset(&sigmask);                            /* All signals */
+(void)sigdelset(&sigmask, SIGALRM);                    /* Remove SIGALRM */
+(void)sigsuspend(&sigmask);                            /* Until SIGALRM */
+(void)sigprocmask(SIG_SETMASK, &old_sigmask, NULL);    /* Restore mask */
+}
+
+static void
+millisleep(int msec)
+{
+struct itimerval itval;
+itval.it_interval.tv_sec = 0;
+itval.it_interval.tv_usec = 0;
+itval.it_value.tv_sec = msec/1000;
+itval.it_value.tv_usec = (msec % 1000) * 1000;
+milliwait(&itval);
+}
+
+
 /*************************************************
 *              Scan file for RRs                 *
 *************************************************/
@@ -283,6 +319,7 @@ while (fgets(CS buffer, sizeof(buffer), f) != NULL)
   int tvalue = typeptr->value;
   int qtlen = qtypelen;
   BOOL rr_sec = FALSE;
+  int delay = 0;
 
   p = buffer;
   while (isspace(*p)) p++;
@@ -299,11 +336,22 @@ while (fgets(CS buffer, sizeof(buffer), f) != NULL)
   *ep = 0;
 
   p = buffer;
-  if (Ustrncmp(p, US"DNSSEC ", 7) == 0)        /* tagged as secure */
-    {
-    rr_sec = TRUE;
-    p += 7;
-    }
+  for (;;)
+       {
+       if (Ustrncmp(p, US"DNSSEC ", 7) == 0)   /* tagged as secure */
+         {
+         rr_sec = TRUE;
+         p += 7;
+         }
+       else if (Ustrncmp(p, US"DELAY=", 6) == 0)       /* delay beforee response */
+         {
+         for (p += 6; *p >= '0' && *p <= '9'; p++)
+               delay = delay*10 + *p - '0';
+         while (isspace(*p)) p++;
+         }
+       else
+         break;
+       }
 
   if (!isspace(*p))
     {
@@ -357,6 +405,9 @@ while (fgets(CS buffer, sizeof(buffer), f) != NULL)
 
   /* Found a relevant record */
 
+  if (delay)
+    millisleep(delay);
+
   if (!rr_sec)
     *dnssec = FALSE;                   /* cancel AD return */
 
@@ -482,6 +533,10 @@ return (yield == HOST_NOT_FOUND && pass_on_not_found)? PASS_ON : yield;
 }
 
 
+static  void
+alarmfn(int sig)
+{
+}
 
 /*************************************************
 *           Entry point and main program         *
@@ -508,6 +563,8 @@ uschar packet[512];
 uschar *pk = packet;
 BOOL dnssec;
 
+signal(SIGALRM, alarmfn);
+
 if (argc != 4)
   {
   fprintf(stderr, "fakens: expected 3 arguments, received %d\n", argc-1);
diff --git a/test/stderr/0606 b/test/stderr/0606
new file mode 100644 (file)
index 0000000..66e14a0
--- /dev/null
@@ -0,0 +1,39 @@
+>>> host in hosts_connection_nolog? no (option unset)
+>>> host in host_lookup? no (option unset)
+>>> host in host_reject_connection? no (option unset)
+>>> host in sender_unqualified_hosts? no (option unset)
+>>> host in recipient_unqualified_hosts? no (option unset)
+>>> host in helo_verify_hosts? no (option unset)
+>>> host in helo_try_verify_hosts? no (option unset)
+>>> host in helo_accept_junk_hosts? no (option unset)
+>>> test in helo_lookup_domains? no (end of list)
+>>> processing "accept"
+>>> check verify = recipient
+>>> >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+>>> routing should_log@delay1500.test.ex
+>>> calling all router
+LOG: Long name lookup for 'delay1500.test.ex': ssss msec
+>>> local host found for non-MX address
+>>> routed by all router
+>>> ----------- end verify ------------
+>>> accept: condition test succeeded in inline ACL
+>>> end of inline ACL: ACCEPT
+>>> host in hosts_connection_nolog? no (option unset)
+>>> host in host_lookup? no (option unset)
+>>> host in host_reject_connection? no (option unset)
+>>> host in sender_unqualified_hosts? no (option unset)
+>>> host in recipient_unqualified_hosts? no (option unset)
+>>> host in helo_verify_hosts? no (option unset)
+>>> host in helo_try_verify_hosts? no (option unset)
+>>> host in helo_accept_junk_hosts? no (option unset)
+>>> test in helo_lookup_domains? no (end of list)
+>>> processing "accept"
+>>> check verify = recipient
+>>> >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+>>> routing should_not_log@delay500.test.ex
+>>> calling all router
+>>> local host found for non-MX address
+>>> routed by all router
+>>> ----------- end verify ------------
+>>> accept: condition test succeeded in inline ACL
+>>> end of inline ACL: ACCEPT
diff --git a/test/stdout/0606 b/test/stdout/0606
new file mode 100644 (file)
index 0000000..5ea77a3
--- /dev/null
@@ -0,0 +1,20 @@
+
+**** SMTP testing session as if from host 127.0.0.1
+**** but without any ident (RFC 1413) callback.
+**** This is not for real!
+
+220 the.local.host.name ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000\r
+250 the.local.host.name Hello test [127.0.0.1]\r
+250 OK\r
+250 Accepted\r
+221 the.local.host.name closing connection\r
+
+**** SMTP testing session as if from host 127.0.0.1
+**** but without any ident (RFC 1413) callback.
+**** This is not for real!
+
+220 the.local.host.name ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000\r
+250 the.local.host.name Hello test [127.0.0.1]\r
+250 OK\r
+250 Accepted\r
+221 the.local.host.name closing connection\r