From: Jeremy Harris Date: Thu, 7 May 2015 20:36:22 +0000 (+0100) Subject: Log lengthy DNS lookups. Bug 514 X-Git-Tag: exim-4_86_RC1~46 X-Git-Url: https://git.exim.org/users/jgh/exim.git/commitdiff_plain/846430d945e9056842ad7f12f85d43435d78baf0 Log lengthy DNS lookups. Bug 514 Original by , massaged by JH --- diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt index bc34d65b8..9baaad233 100644 --- a/doc/doc-docbook/spec.xfpt +++ b/doc/doc-docbook/spec.xfpt @@ -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 diff --git a/doc/doc-txt/NewStuff b/doc/doc-txt/NewStuff index cac6f7c10..aa60f46f1 100644 --- a/doc/doc-txt/NewStuff +++ b/doc/doc-txt/NewStuff @@ -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 ------------ diff --git a/src/src/globals.c b/src/src/globals.c index 868b27e83..3cbbbd311 100644 --- a/src/src/globals.c +++ b/src/src/globals.c @@ -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; diff --git a/src/src/globals.h b/src/src/globals.h index 8aa69bff6..d90854cbe 100644 --- a/src/src/globals.h +++ b/src/src/globals.h @@ -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 */ diff --git a/src/src/host.c b/src/src/host.c index 4d76fc4a3..45ec13659 100644 --- a/src/src/host.c +++ b/src/src/host.c @@ -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 * diff --git a/src/src/readconf.c b/src/src/readconf.c index 67241cb36..dfede671e 100644 --- a/src/src/readconf.c +++ b/src/src/readconf.c @@ -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 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: +rcpt to: +quit +**** +# +# +exim -bh 127.0.0.1 +helo test +mail from: +rcpt to: +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 #include #include +#include #include #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