Log lengthy DNS lookups. Bug 514

    Original by <derrick.rice@gmail.com>, massaged by JH

7 files changed, 173 insertions, 5 deletions

diff --git a/test/confs/0606 b/test/confs/0606
new file mode 100644
index 000000000..538e859de
--- /dev/null
+++ b/test/confs/0606
@@ -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
+
diff --git a/test/dnszones-src/db.test.ex b/test/dnszones-src/db.test.ex
index ab1643452..1339981c8 100644
--- a/test/dnszones-src/db.test.ex
+++ b/test/dnszones-src/db.test.ex
@@ -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
diff --git a/test/runtest b/test/runtest
index f215bf4de..62ab01bac 100755
--- a/test/runtest
+++ b/test/runtest
@@ -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
index 000000000..689978428
--- /dev/null
+++ b/test/scripts/0000-Basic/0606
@@ -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
+****
diff --git a/test/src/fakens.c b/test/src/fakens.c
index baabf1d30..1228c70f9 100644
--- a/test/src/fakens.c
+++ b/test/src/fakens.c
@@ -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
index 000000000..66e14a0f1
--- /dev/null
+++ b/test/stderr/0606
@@ -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
index 000000000..5ea77a338
--- /dev/null
+++ b/test/stdout/0606
@@ -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

+250 the.local.host.name Hello test [127.0.0.1]

+250 OK

+250 Accepted

+221 the.local.host.name closing connection

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

+250 the.local.host.name Hello test [127.0.0.1]

+250 OK

+250 Accepted

+221 the.local.host.name closing connection