Add DNS debug aid if we requested AD but got AA
[users/heiko/exim.git] / src / src / host.c
index 4d76fc4a3df304b3fd1b0b713899adf2ce47ce41..3c685b0e4686c26e18bdae3ec3ff3f9356cf07b4 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;
+}
 
 
 /*************************************************
@@ -101,8 +148,7 @@ return (unsigned int)(random_seed >> 16) % limit;
 *************************************************/
 
 /* This function is called instead of gethostbyname(), gethostbyname2(), or
-getipnodebyname() when running in the test harness. It recognizes the name
-"manyhome.test.ex" and generates a humungous number of IP addresses. It also
+getipnodebyname() when running in the test harness. . It also
 recognizes an unqualified "localhost" and forces it to the appropriate loopback
 address. IP addresses are treated as literals. For other names, it uses the DNS
 to find the host name. In the test harness, this means it will access only the
@@ -139,34 +185,6 @@ DEBUG(D_host_lookup)
   debug_printf("using host_fake_gethostbyname for %s (%s)\n", name,
     (af == AF_INET)? "IPv4" : "IPv6");
 
-/* Handle the name that needs a vast number of IP addresses */
-
-if (Ustrcmp(name, "manyhome.test.ex") == 0 && af == AF_INET)
-  {
-  int i, j;
-  yield = store_get(sizeof(struct hostent));
-  alist = store_get(2049 * sizeof(char *));
-  adds  = store_get(2048 * alen);
-  yield->h_name = CS name;
-  yield->h_aliases = NULL;
-  yield->h_addrtype = af;
-  yield->h_length = alen;
-  yield->h_addr_list = CSS alist;
-  for (i = 104; i <= 111; i++)
-    {
-    for (j = 0; j <= 255; j++)
-      {
-      *alist++ = adds;
-      *adds++ = 10;
-      *adds++ = 250;
-      *adds++ = i;
-      *adds++ = j;
-      }
-    }
-  *alist = NULL;
-  return yield;
-  }
-
 /* Handle unqualified "localhost" */
 
 if (Ustrcmp(name, "localhost") == 0)
@@ -217,7 +235,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;
@@ -233,11 +251,10 @@ else
     }
 
   for (rr = dns_next_rr(&dnsa, &dnss, RESET_ANSWERS);
-       rr != NULL;
+       rr;
        rr = dns_next_rr(&dnsa, &dnss, RESET_NEXT))
-    {
-    if (rr->type == type) count++;
-    }
+    if (rr->type == type)
+      count++;
 
   yield = store_get(sizeof(struct hostent));
   alist = store_get((count + 1) * sizeof(char **));
@@ -250,14 +267,14 @@ else
   yield->h_addr_list = CSS alist;
 
   for (rr = dns_next_rr(&dnsa, &dnss, RESET_ANSWERS);
-       rr != NULL;
+       rr;
        rr = dns_next_rr(&dnsa, &dnss, RESET_NEXT))
     {
     int i, n;
     int x[4];
     dns_address *da;
     if (rr->type != type) continue;
-    da = dns_address_from_rr(&dnsa, rr);
+    if (!(da = dns_address_from_rr(&dnsa, rr))) break;
     *alist++ = adds;
     n = host_aton(da->address, x);
     for (i = 0; i < n; i++)
@@ -1454,6 +1471,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 +1509,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)
@@ -1614,14 +1639,13 @@ if (running_in_test_harness &&
 /* Do lookups directly in the DNS or via gethostbyaddr() (or equivalent), in
 the order specified by the host_lookup_order option. */
 
-while ((ordername = string_nextinlist(&list, &sep, buffer, sizeof(buffer)))
-        != NULL)
+while ((ordername = string_nextinlist(&list, &sep, buffer, sizeof(buffer))))
   {
   if (strcmpic(ordername, US"bydns") == 0)
     {
     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
@@ -1636,8 +1660,6 @@ while ((ordername = string_nextinlist(&list, &sep, buffer, sizeof(buffer)))
       int count = 0;
       int old_pool = store_pool;
 
-      /* Ideally we'd check DNSSEC both forward and reverse, but we use the
-      gethost* routines for forward, so can't do that unless/until we rewrite. */
       sender_host_dnssec = dns_is_secure(&dnsa);
       DEBUG(D_dns)
         debug_printf("Reverse DNS security status: %s\n",
@@ -1646,11 +1668,10 @@ while ((ordername = string_nextinlist(&list, &sep, buffer, sizeof(buffer)))
       store_pool = POOL_PERM;        /* Save names in permanent storage */
 
       for (rr = dns_next_rr(&dnsa, &dnss, RESET_ANSWERS);
-           rr != NULL;
+           rr;
            rr = dns_next_rr(&dnsa, &dnss, RESET_NEXT))
-        {
-        if (rr->type == T_PTR) count++;
-        }
+        if (rr->type == T_PTR)
+         count++;
 
       /* Get store for the list of aliases. For compatibility with
       gethostbyaddr, we make an empty list if there are none. */
@@ -1660,7 +1681,7 @@ while ((ordername = string_nextinlist(&list, &sep, buffer, sizeof(buffer)))
       /* Re-scan and extract the names */
 
       for (rr = dns_next_rr(&dnsa, &dnss, RESET_ANSWERS);
-           rr != NULL;
+           rr;
            rr = dns_next_rr(&dnsa, &dnss, RESET_NEXT))
         {
         uschar *s = NULL;
@@ -1685,8 +1706,8 @@ while ((ordername = string_nextinlist(&list, &sep, buffer, sizeof(buffer)))
             "empty name: treated as non-existent host name\n");
           continue;
           }
-        if (sender_host_name == NULL) sender_host_name = s;
-          else *aptr++ = s;
+        if (!sender_host_name) sender_host_name = s;
+       else *aptr++ = s;
         while (*s != 0) { *s = tolower(*s); s++; }
         }
 
@@ -1765,21 +1786,30 @@ for (hname = sender_host_name; hname != NULL; hname = *aliases++)
   int rc;
   BOOL ok = FALSE;
   host_item h;
+  dnssec_domains d;
+
   h.next = NULL;
   h.name = hname;
   h.mx = MX_NONE;
   h.address = NULL;
+  d.request = sender_host_dnssec ? US"*" : NULL;;
+  d.require = NULL;
 
-  /* When called with the last argument FALSE, host_find_byname() won't return
-  HOST_FOUND_LOCAL. If the incoming address is an IPv4 address expressed in
-  IPv6 format, we must compare the IPv4 part to any IPv4 addresses. */
-
-  if ((rc = host_find_byname(&h, NULL, 0, NULL, FALSE)) == HOST_FOUND)
+  if (  (rc = host_find_bydns(&h, NULL, HOST_FIND_BY_A,
+         NULL, NULL, NULL, &d, NULL, NULL)) == HOST_FOUND
+     || rc == HOST_FOUND_LOCAL
+     )
     {
     host_item *hh;
     HDEBUG(D_host_lookup) debug_printf("checking addresses for %s\n", hname);
+
+    /* If the forward lookup was not secure we cancel the is-secure variable */
+
+    DEBUG(D_dns) debug_printf("Forward DNS security status: %s\n",
+         h.dnssec == DS_YES ? "DNSSEC verified (AD)" : "unverified");
+    if (h.dnssec != DS_YES) sender_host_dnssec = FALSE;
+
     for (hh = &h; hh != NULL; hh = hh->next)
-      {
       if (host_is_in_net(hh->address, sender_host_address, 0))
         {
         HDEBUG(D_host_lookup) debug_printf("  %s OK\n", hh->address);
@@ -1787,10 +1817,8 @@ for (hname = sender_host_name; hname != NULL; hname = *aliases++)
         break;
         }
       else
-        {
         HDEBUG(D_host_lookup) debug_printf("  %s\n", hh->address);
-        }
-      }
+
     if (!ok) HDEBUG(D_host_lookup)
       debug_printf("no IP address for %s matched %s\n", hname,
         sender_host_address);
@@ -1803,9 +1831,7 @@ for (hname = sender_host_name; hname != NULL; hname = *aliases++)
     return DEFER;
     }
   else
-    {
     HDEBUG(D_host_lookup) debug_printf("no IP addresses found for %s\n", hname);
-    }
 
   /* If this name is no good, and it's the sender name, set it null pro tem;
   if it's an alias, just remove it from the list. */
@@ -1917,7 +1943,7 @@ some circumstances when the get..byname() function actually calls the DNS. */
 
 dns_init((flags & HOST_FIND_QUALIFY_SINGLE) != 0,
          (flags & HOST_FIND_SEARCH_PARENTS) != 0,
-        FALSE);        /*XXX dnssec? */
+        FALSE);                /* Cannot retrieve dnssec status so do not request */
 
 /* In an IPv6 world, unless IPv6 has been disabled, we need to scan for both
 kinds of address, so go round the loop twice. Note that we have ensured that
@@ -1961,11 +1987,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 +2018,10 @@ 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;
@@ -2195,7 +2228,8 @@ Arguments:
   fully_qualified_name  if not NULL, return fully qualified name here if
                           the contents are different (i.e. it must be preset
                           to something)
-  dnnssec_require      if TRUE check the DNS result AD bit
+  dnssec_request       if TRUE request the AD bit
+  dnssec_require       if TRUE require the AD bit
 
 Returns:       HOST_FIND_FAILED     couldn't find A record
                HOST_FIND_AGAIN      try again later
@@ -2263,10 +2297,16 @@ 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";
 
+  DEBUG(D_dns)
+    if ((dnssec_request || dnssec_require)
+       & !dns_is_secure(&dnsa)
+       & dns_is_aa(&dnsa))
+      debug_printf("DNS lookup of %.256s (A/AAA/A6) requested AD, but got AA\n", host->name);
+
   /* We want to return HOST_FIND_AGAIN if one of the A, A6, or AAAA lookups
   fails or times out, but not if another one succeeds. (In the early
   IPv6 days there are name servers that always fail on AAAA, but are happy
@@ -2317,10 +2357,13 @@ for (; i >= 0; i--)
 
   /* Lookup succeeded: fill in the given host item with the first non-ignored
   address found; create additional items for any others. A single A6 record
-  may generate more than one address. */
+  may generate more than one address.  The lookup had a chance to update the
+  fqdn; we do not want any later times round the loop to do so. */
+
+  fully_qualified_name = NULL;
 
   for (rr = dns_next_rr(&dnsa, &dnss, RESET_ANSWERS);
-       rr != NULL;
+       rr;
        rr = dns_next_rr(&dnsa, &dnss, RESET_NEXT))
     {
     if (rr->type == type)
@@ -2332,15 +2375,14 @@ for (; i >= 0; i--)
 
       DEBUG(D_host_lookup)
         {
-        if (da == NULL)
-          debug_printf("no addresses extracted from A6 RR for %s\n",
+        if (!da) debug_printf("no addresses extracted from A6 RR for %s\n",
             host->name);
         }
 
       /* This loop runs only once for A and AAAA records, but may run
       several times for an A6 record that generated multiple addresses. */
 
-      for (; da != NULL; da = da->next)
+      for (; da; da = da->next)
         {
         #ifndef STAND_ALONE
         if (ignore_target_hosts != NULL &&
@@ -2460,8 +2502,8 @@ Arguments:
   srv_service           when SRV used, the service name
   srv_fail_domains      DNS errors for these domains => assume nonexist
   mx_fail_domains       DNS errors for these domains => assume nonexist
-  dnssec_request_domains => make dnssec request
-  dnssec_require_domains => ditto and nonexist failures
+  dnssec_d.request =>   make dnssec request: domainlist
+  dnssec_d.require =>   ditto and nonexist failures
   fully_qualified_name  if not NULL, return fully-qualified name
   removed               set TRUE if local host was removed from the list
 
@@ -2479,7 +2521,7 @@ Returns:                HOST_FIND_FAILED  Failed to find the host or domain;
 int
 host_find_bydns(host_item *host, const uschar *ignore_target_hosts, int whichrrs,
   uschar *srv_service, uschar *srv_fail_domains, uschar *mx_fail_domains,
-  uschar *dnssec_request_domains, uschar *dnssec_require_domains,
+  const dnssec_domains *dnssec_d,
   const uschar **fully_qualified_name, BOOL *removed)
 {
 host_item *h, *last;
@@ -2489,11 +2531,13 @@ int ind_type = 0;
 int yield;
 dns_answer dnsa;
 dns_scan dnss;
-BOOL dnssec_require = match_isinlist(host->name, CUSS &dnssec_require_domains,
+BOOL dnssec_require = dnssec_d
+                   && match_isinlist(host->name, CUSS &dnssec_d->require,
                                    0, NULL, NULL, MCL_DOMAIN, TRUE, NULL) == OK;
 BOOL dnssec_request = dnssec_require
-                   || match_isinlist(host->name, CUSS &dnssec_request_domains,
-                                   0, NULL, NULL, MCL_DOMAIN, TRUE, NULL) == OK;
+                   || (  dnssec_d
+                      && match_isinlist(host->name, CUSS &dnssec_d->request,
+                                   0, NULL, NULL, MCL_DOMAIN, TRUE, NULL) == OK);
 dnssec_status_t dnssec;
 
 /* Set the default fully qualified name to the incoming name, initialize the
@@ -2503,12 +2547,11 @@ that gets set for DNS syntax check errors. */
 if (fully_qualified_name != NULL) *fully_qualified_name = host->name;
 dns_init((whichrrs & HOST_FIND_QUALIFY_SINGLE) != 0,
          (whichrrs & HOST_FIND_SEARCH_PARENTS) != 0,
-        dnssec_request
-        );
+        dnssec_request);
 host_find_failed_syntax = FALSE;
 
 /* First, if requested, look for SRV records. The service name is given; we
-assume TCP progocol. DNS domain names are constrained to a maximum of 256
+assume TCP protocol. DNS domain names are constrained to a maximum of 256
 characters, so the code below should be safe. */
 
 if ((whichrrs & HOST_FIND_BY_SRV) != 0)
@@ -2527,7 +2570,13 @@ 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);
+
+  DEBUG(D_dns)
+    if ((dnssec_request || dnssec_require)
+       & !dns_is_secure(&dnsa)
+       & dns_is_aa(&dnsa))
+      debug_printf("DNS lookup of %.256s (SRV) requested AD, but got AA\n", host->name);
 
   if (dnssec_request)
     {
@@ -2573,7 +2622,13 @@ 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);
+
+  DEBUG(D_dns)
+    if ((dnssec_request || dnssec_require)
+       & !dns_is_secure(&dnsa)
+       & dns_is_aa(&dnsa))
+      debug_printf("DNS lookup of %.256s (MX) requested AD, but got AA\n", host->name);
 
   if (dnssec_request)
     {
@@ -3079,9 +3134,6 @@ dns_init(FALSE, FALSE, FALSE);    /* clear the dnssec bit for getaddrbyname */
 return yield;
 }
 
-
-
-
 /*************************************************
 **************************************************
 *             Stand-alone test program           *
@@ -3172,6 +3224,7 @@ while (Ufgets(buffer, 256, stdin) != NULL)
   else
     {
     int flags = whichrrs;
+    dnssec d;
 
     h.name = buffer;
     h.next = NULL;
@@ -3184,12 +3237,13 @@ while (Ufgets(buffer, 256, stdin) != NULL)
     if (qualify_single) flags |= HOST_FIND_QUALIFY_SINGLE;
     if (search_parents) flags |= HOST_FIND_SEARCH_PARENTS;
 
+    d.request = request_dnssec ? &h.name : NULL;
+    d.require = require_dnssec ? &h.name : NULL;
+
     rc = byname
       ? host_find_byname(&h, NULL, flags, &fully_qualified_name, TRUE)
       : host_find_bydns(&h, NULL, flags, US"smtp", NULL, NULL,
-                       request_dnssec ? &h.name : NULL,
-                       require_dnssec ? &h.name : NULL,
-                       &fully_qualified_name, NULL);
+                       &d, &fully_qualified_name, NULL);
 
     if (rc == HOST_FIND_FAILED) printf("Failed\n");
       else if (rc == HOST_FIND_AGAIN) printf("Again\n");