.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"
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
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
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
------------
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;
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 */
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;
+}
/*************************************************
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;
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 */
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)
{
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
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);
}
#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;
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";
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)
{
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)
{
return yield;
}
-
-
-
/*************************************************
**************************************************
* Stand-alone test program *
{ "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 },
--- /dev/null
+# 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
+
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
'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/' },
+
};
--- /dev/null
+# 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
+****
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. */
#include <errno.h>
#include <arpa/nameser.h>
#include <sys/types.h>
+#include <sys/time.h>
#include <dirent.h>
#define FALSE 0
+/*************************************************/
+
+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 *
*************************************************/
int tvalue = typeptr->value;
int qtlen = qtypelen;
BOOL rr_sec = FALSE;
+ int delay = 0;
p = buffer;
while (isspace(*p)) p++;
*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))
{
/* Found a relevant record */
+ if (delay)
+ millisleep(delay);
+
if (!rr_sec)
*dnssec = FALSE; /* cancel AD return */
}
+static void
+alarmfn(int sig)
+{
+}
/*************************************************
* Entry point and main program *
uschar *pk = packet;
BOOL dnssec;
+signal(SIGALRM, alarmfn);
+
if (argc != 4)
{
fprintf(stderr, "fakens: expected 3 arguments, received %d\n", argc-1);
--- /dev/null
+>>> 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
--- /dev/null
+
+**** 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
projects / exim.git / commitdiff