From: Jeremy Harris Date: Sun, 21 Jul 2013 17:03:29 +0000 (+0100) Subject: Merge branch 'master' into transp_logging_1031 X-Git-Url: https://git.exim.org/users/jgh/exim.git/commitdiff_plain/9162b43bbdc6f71cffbc92489d33ea204b76bad4?hp=351a5bc85e6950e3608c41f1bd15368b0a49d5f3 Merge branch 'master' into transp_logging_1031 --- diff --git a/doc/doc-txt/experimental-spec.txt b/doc/doc-txt/experimental-spec.txt index 7fd2bd8ec..a7651f6c0 100644 --- a/doc/doc-txt/experimental-spec.txt +++ b/doc/doc-txt/experimental-spec.txt @@ -844,6 +844,91 @@ b. Configure, somewhere before the DATA ACL, the control option to +DBL (Database Logging) +-------------------------------------------------------------- + +An arbitrary per-transport string can be expanded on successful delivery, +and (for SMTP transports) a second string on deferrals caused by a host error. +This feature allows the writing of exim internal log information +(not available otherwise) into a database. + +In order to use DBL, you must set + +EXPERIMENTAL_DBL=yes + +in your Local/Makefile + +and define the expandable strings in the runtime config file, to +be executed at end of delivery. + +Additionally, there are 8 more variables, available at end of +delivery: + +dbl_delivery_ip IP of host, which has accepted delivery +dbl_delivery_port Port of remote host which has accepted delivery +dbl_delivery_fqdn FQDN of host, which has accepted delivery +dbl_delivery_local_part local part of address being delivered +dbl_delivery_domain domain part of address being delivered +dbl_delivery_confirmation SMTP confirmation message +router_name name of router +transport_name name of transport + +In case of a deferral caused by a host-error: +dbl_defer_errno Error number +dbl_defer_errstr Error string possibly containing more details + + + +To log successful deliveries, set the following option +on any transport of interest. + +dbl_delivery_query + +An example might look like: + +dbl_delivery_query = \ +${lookup pgsql {SELECT * FROM record_Delivery( \ + '${quote_pgsql:$sender_address_domain}',\ + '${quote_pgsql:${lc:$sender_address_local_part}}', \ + '${quote_pgsql:$dbl_delivery_domain}', \ + '${quote_pgsql:${lc:$dbl_delivery_local_part}}', \ + '${quote_pgsql:$dbl_delivery_ip}', \ + '${quote_pgsql:${lc:$dbl_delivery_fqdn}}', \ + '${quote_pgsql:$message_exim_id}')}} + +The string is expanded after the delivery completes and any +side-effects will happen. The result is then discarded. +Note that for complex operations an ACL expansion can be used. + + +In order to log host deferrals, add the following option to an SMTP +transport: + +dbl_host_defer_query + +This is a private option of the SMTP transport. It is intended to +log failures of remote hosts. It is executed only when exim has +attempted to deliver a message to a remote host and failed due to +an error which doesn't seem to be related to the individual +message, sender, or recipient address. +See section 45.2 of the exim documentation for more details on how +this is determined. + +Example: + +dbl_host_defer_query = \ +${lookup mysql {insert into delivlog set \ + msgid = '${quote_mysql:$message_exim_id}', \ + senderlp = '${quote_mysql:${lc:$sender_address_local_part}}', \ + senderdom = '${quote_mysql:$sender_address_domain}', \ + delivlp = '${quote_mysql:${lc:$dbl_delivery_local_part}}', \ + delivdom = '${quote_mysql:$dbl_delivery_domain}', \ + delivip = '${quote_mysql:$dbl_delivery_ip}', \ + delivport = '${quote_mysql:$dbl_delivery_port}', \ + delivfqdn = '${quote_mysql:$dbl_delivery_fqdn}', \ + deliverrno = '${quote_mysql:$dbl_defer_errno}', \ + deliverrstr = '${quote_mysql:$dbl_defer_errstr}' \ + }} -------------------------------------------------------------- End of file diff --git a/src/src/EDITME b/src/src/EDITME index e29c1eb25..637256c7d 100644 --- a/src/src/EDITME +++ b/src/src/EDITME @@ -469,6 +469,10 @@ EXIM_MONITOR=eximon.bin # Uncomment the following line to add Per-Recipient-Data-Response support. # EXPERIMENTAL_PRDR=yes +# This feature allows to write log information about a completed +# delivery into a database +# EXPERIMENTAL_DBL=yes + ############################################################################### # THESE ARE THINGS YOU MIGHT WANT TO SPECIFY # diff --git a/src/src/config.h.defaults b/src/src/config.h.defaults index 1594f6858..bcbc70b38 100644 --- a/src/src/config.h.defaults +++ b/src/src/config.h.defaults @@ -170,6 +170,7 @@ it's a default value. */ #define EXPERIMENTAL_PRDR #define EXPERIMENTAL_SPF #define EXPERIMENTAL_SRS +#define EXPERIMENTAL_DBL /* For developers */ #define WANT_DEEPER_PRINTF_CHECKS diff --git a/src/src/deliver.c b/src/src/deliver.c index 23e63d553..5e4a2a1e1 100644 --- a/src/src/deliver.c +++ b/src/src/deliver.c @@ -695,6 +695,15 @@ the log line, and reset the store afterwards. Remote deliveries should always have a pointer to the host item that succeeded; local deliveries can have a pointer to a single host item in their host list, for use by the transport. */ +#ifdef EXPERIMENTAL_DBL + dbl_delivery_ip = NULL; /* presume no successful remote delivery */ + dbl_delivery_port = 0; + dbl_delivery_fqdn = NULL; + dbl_delivery_local_part = NULL; + dbl_delivery_domain = NULL; + dbl_delivery_confirmation = NULL; +#endif + s = reset_point = store_get(size); log_address = string_log_address(addr, (log_write_selector & L_all_parents) != 0, TRUE); @@ -741,7 +750,12 @@ if ((log_extra_selector & LX_delivery_size) != 0) if (addr->transport->info->local) { if (addr->host_list != NULL) + { s = string_append(s, &size, &ptr, 2, US" H=", addr->host_list->name); + #ifdef EXPERIMENTAL_DBL + dbl_delivery_fqdn = addr->host_list->name; + #endif + } if (addr->shadow_message != NULL) s = string_cat(s, &size, &ptr, addr->shadow_message, Ustrlen(addr->shadow_message)); @@ -760,6 +774,15 @@ else addr->host_used->port)); if (continue_sequence > 1) s = string_cat(s, &size, &ptr, US"*", 1); + + #ifdef EXPERIMENTAL_DBL + dbl_delivery_ip = addr->host_used->address; + dbl_delivery_port = addr->host_used->port; + dbl_delivery_fqdn = addr->host_used->name; + dbl_delivery_local_part = addr->local_part; + dbl_delivery_domain = addr->domain; + dbl_delivery_confirmation = addr->message; + #endif } #ifdef SUPPORT_TLS @@ -827,6 +850,22 @@ store we used to build the line after writing it. */ s[ptr] = 0; log_write(0, flags, "%s", s); + +#ifdef EXPERIMENTAL_DBL +if (addr->transport->dbl_delivery_query) + { + DEBUG(D_deliver) + { + debug_printf(" DBL(Delivery): dbl_delivery_query=|%s| dbl_delivery_IP=%s\n", + addr->transport->dbl_delivery_query, dbl_delivery_ip); + } + router_name = addr->router->name; + transport_name = addr->transport->name; + expand_string(addr->transport->dbl_delivery_query); + router_name = NULL; + transport_name = NULL; + } +#endif store_reset(reset_point); return; } diff --git a/src/src/exim.c b/src/src/exim.c index 8ab0456d8..1d3d32723 100644 --- a/src/src/exim.c +++ b/src/src/exim.c @@ -825,6 +825,9 @@ fprintf(f, "Support for:"); #ifdef EXPERIMENTAL_PRDR fprintf(f, " Experimental_PRDR"); #endif +#ifdef EXPERIMENTAL_DBL + fprintf(f, " Experimental_DBL"); +#endif fprintf(f, "\n"); fprintf(f, "Lookups (built-in):"); diff --git a/src/src/expand.c b/src/src/expand.c index 1da222563..d808d1bf3 100644 --- a/src/src/expand.c +++ b/src/src/expand.c @@ -431,6 +431,16 @@ static var_entry var_table[] = { { "compile_date", vtype_stringptr, &version_date }, { "compile_number", vtype_stringptr, &version_cnumber }, { "csa_status", vtype_stringptr, &csa_status }, +#ifdef EXPERIMENTAL_DBL + { "dbl_defer_errno", vtype_int, &dbl_defer_errno }, + { "dbl_defer_errstr", vtype_stringptr, &dbl_defer_errstr }, + { "dbl_delivery_confirmation", vtype_stringptr, &dbl_delivery_confirmation }, + { "dbl_delivery_domain", vtype_stringptr, &dbl_delivery_domain }, + { "dbl_delivery_fqdn", vtype_stringptr, &dbl_delivery_fqdn }, + { "dbl_delivery_ip", vtype_stringptr, &dbl_delivery_ip }, + { "dbl_delivery_local_part",vtype_stringptr,&dbl_delivery_local_part }, + { "dbl_delivery_port", vtype_int, &dbl_delivery_port }, +#endif #ifdef EXPERIMENTAL_DCC { "dcc_header", vtype_stringptr, &dcc_header }, { "dcc_result", vtype_stringptr, &dcc_result }, diff --git a/src/src/globals.c b/src/src/globals.c index 74b6edb01..2345ac4e1 100644 --- a/src/src/globals.c +++ b/src/src/globals.c @@ -483,6 +483,17 @@ uschar *daemon_smtp_port = US"smtp"; int daemon_startup_retries = 9; int daemon_startup_sleep = 30; +#ifdef EXPERIMENTAL_DBL +int dbl_defer_errno = 0; +uschar *dbl_defer_errstr = NULL; +uschar *dbl_delivery_ip = NULL; +int dbl_delivery_port = 0; +uschar *dbl_delivery_fqdn = NULL; +uschar *dbl_delivery_local_part= NULL; +uschar *dbl_delivery_domain = NULL; +uschar *dbl_delivery_confirmation = NULL; +#endif + #ifdef EXPERIMENTAL_DCC BOOL dcc_direct_add_header = FALSE; uschar *dcc_header = NULL; diff --git a/src/src/globals.h b/src/src/globals.h index db436c06d..ad36bf79f 100644 --- a/src/src/globals.h +++ b/src/src/globals.h @@ -283,6 +283,17 @@ extern uschar *dccifd_address; /* address of the dccifd daemon */ extern uschar *dccifd_options; /* options for the dccifd daemon */ #endif +#ifdef EXPERIMENTAL_DBL +extern int dbl_defer_errno; /* error number set when a remote delivery is deferred with a host error */ +extern uschar *dbl_defer_errstr; /* error string set when a remote delivery is deferred with a host error */ +extern uschar *dbl_delivery_ip; /* IP of host, which has accepted delivery */ +extern int dbl_delivery_port; /* port of host, which has accepted delivery */ +extern uschar *dbl_delivery_fqdn; /* FQDN of host, which has accepted delivery */ +extern uschar *dbl_delivery_local_part;/* local part of address being delivered */ +extern uschar *dbl_delivery_domain; /* domain part of address being delivered */ +extern uschar *dbl_delivery_confirmation; /* SMTP confirmation message */ +#endif + extern BOOL debug_daemon; /* Debug the daemon process only */ extern int debug_fd; /* The fd for debug_file */ extern FILE *debug_file; /* Where to write debugging info */ diff --git a/src/src/structs.h b/src/src/structs.h index 53aa2106b..d7f01c3b4 100644 --- a/src/src/structs.h +++ b/src/src/structs.h @@ -184,6 +184,9 @@ typedef struct transport_instance { BOOL log_fail_output; BOOL log_defer_output; BOOL retry_use_local_part; /* Defaults true for local, false for remote */ +#ifdef EXPERIMENTAL_DBL + uschar *dbl_delivery_query; /* String to expand on success */ +#endif } transport_instance; diff --git a/src/src/transport.c b/src/src/transport.c index 7dd1afb85..ef00fe275 100644 --- a/src/src/transport.c +++ b/src/src/transport.c @@ -56,6 +56,10 @@ optionlist optionlist_transports[] = { (void *)offsetof(transport_instance, body_only) }, { "current_directory", opt_stringptr|opt_public, (void *)offsetof(transport_instance, current_dir) }, +#ifdef EXPERIMENTAL_DBL + { "dbl_delivery_query",opt_stringptr | opt_public, + (void *)offsetof(transport_instance, dbl_delivery_query) }, +#endif { "debug_print", opt_stringptr | opt_public, (void *)offsetof(transport_instance, debug_string) }, { "delivery_date_add", opt_bool|opt_public, diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c index 25cc5490a..ac24f5f09 100644 --- a/src/src/transports/smtp.c +++ b/src/src/transports/smtp.c @@ -35,6 +35,10 @@ optionlist smtp_transport_options[] = { (void *)offsetof(transport_instance, connection_max_messages) }, { "data_timeout", opt_time, (void *)offsetof(smtp_transport_options_block, data_timeout) }, +#ifdef EXPERIMENTAL_DBL + { "dbl_host_defer_query", opt_stringptr, + (void *)offsetof(smtp_transport_options_block, dbl_host_defer_query) }, +#endif { "delay_after_cutoff", opt_bool, (void *)offsetof(smtp_transport_options_block, delay_after_cutoff) }, #ifndef DISABLE_DKIM @@ -233,6 +237,9 @@ smtp_transport_options_block smtp_transport_option_defaults = { NULL, /* dkim_sign_headers */ NULL /* dkim_strict */ #endif +#ifdef EXPERIMENTAL_DBL + ,NULL /* dbl_host_defer_query */ +#endif }; @@ -577,6 +584,56 @@ else +#ifdef EXPERIMENTAL_DBL +/************************************************* +* Write error message to database log * +*************************************************/ + +/* This expands an arbitrary per-transport string. + It might, for example, be used to write to the database log. + +Arguments: + dbl_host_defer_query dbl_host_defer_query from the transport options block + addr the address item containing error information + host the current host + +Returns: nothing +*/ + +static void +dbl_write_defer_log(uschar *dbl_host_defer_query, address_item *addr, host_item *host) +{ +if (dbl_host_defer_query == NULL) + return; + +dbl_delivery_ip = string_copy(host->address); +dbl_delivery_port = (host->port == PORT_NONE)? 25 : host->port; +dbl_delivery_fqdn = string_copy(host->name); +dbl_delivery_local_part = string_copy(addr->local_part); +dbl_delivery_domain = string_copy(addr->domain); +dbl_defer_errno = addr->basic_errno; + +dbl_defer_errstr = (addr->message != NULL) + ? (addr->basic_errno > 0) + ? string_sprintf("%s: %s", addr->message, strerror(addr->basic_errno)) + : string_copy(addr->message) + : (addr->basic_errno > 0) + ? string_copy(strerror(addr->basic_errno)) + : NULL; + +DEBUG(D_transport) { + debug_printf(" DBL(host defer): dbl_host_defer_query=|%s| dbl_delivery_IP=%s\n", dbl_host_defer_query, dbl_delivery_ip); +} + +router_name = addr->router->name; +transport_name = addr->transport->name; +expand_string(dbl_host_defer_query); +router_name = transport_name = NULL; +} +#endif + + + /************************************************* * Synchronize SMTP responses * *************************************************/ @@ -1912,7 +1969,12 @@ if (!ok) ok = TRUE; else /* Set up confirmation if needed - applies only to SMTP */ - if ((log_extra_selector & LX_smtp_confirmation) != 0 && !lmtp) + if ( + #ifndef EXPERIMENTAL_DBL + (log_extra_selector & LX_smtp_confirmation) != 0 && + #endif + !lmtp + ) { uschar *s = string_printing(buffer); conf = (s == buffer)? (uschar *)string_copy(s) : s; @@ -3051,6 +3113,11 @@ for (cutoff_retry = 0; expired && first_addr->basic_errno != ERRNO_TLSFAILURE) write_logs(first_addr, host); + #ifdef EXPERIMENTAL_DBL + if (rc == DEFER) + dbl_write_defer_log(ob->dbl_host_defer_query, first_addr, host); + #endif + /* If STARTTLS was accepted, but there was a failure in setting up the TLS session (usually a certificate screwup), and the host is not in hosts_require_tls, and tls_tempfail_tryclear is true, try again, with @@ -3073,6 +3140,10 @@ for (cutoff_retry = 0; expired && expanded_hosts != NULL, &message_defer, TRUE); if (rc == DEFER && first_addr->basic_errno != ERRNO_AUTHFAIL) write_logs(first_addr, host); + #ifdef EXPERIMENTAL_DBL + if (rc == DEFER) + dbl_write_defer_log(ob->dbl_host_defer_query, first_addr, host); + #endif } #endif } diff --git a/src/src/transports/smtp.h b/src/src/transports/smtp.h index 8e85294bc..176858525 100644 --- a/src/src/transports/smtp.h +++ b/src/src/transports/smtp.h @@ -73,6 +73,9 @@ typedef struct { uschar *dkim_sign_headers; uschar *dkim_strict; #endif + #ifdef EXPERIMENTAL_DBL + uschar *dbl_host_defer_query; + #endif } smtp_transport_options_block; /* Data for reading the private options. */ diff --git a/test/confs/5700 b/test/confs/5700 new file mode 100644 index 000000000..700b360a8 --- /dev/null +++ b/test/confs/5700 @@ -0,0 +1,60 @@ +# Exim test configuration 5700 + +exim_path = EXIM_PATH +host_lookup_order = bydns +rfc1413_query_timeout = 0s +spool_directory = DIR/spool +log_file_path = DIR/spool/log/%slog +gecos_pattern = "" +gecos_name = CALLER_NAME + +# ----- Main settings ----- + +acl_smtp_rcpt = accept +acl_smtp_data = accept + + +# ----- ACL ----- + +begin acl + +logger: + accept logwrite = \ + $acl_arg1 \ + ip <$dbl_delivery_ip> \ + port <$dbl_delivery_port> \ + fqdn <$dbl_delivery_fqdn> \ + local_part <$dbl_delivery_local_part> \ + domain <$dbl_delivery_domain> \ + confirmation <$dbl_delivery_confirmation> \ + errno <$dbl_defer_errno> \ + errstr <$dbl_defer_errstr> \ + router <$router_name> \ + transport <$transport_name> + + +# ----- Routers ----- + +begin routers + +others: + driver = manualroute + route_list = * 127.0.0.1 byname + self = send + transport = smtp + no_more + + +# ----- Transports ----- + +begin transports + +smtp: + driver = smtp + port = PORT_S + command_timeout = 1s + final_timeout = 1s + dbl_delivery_query = ${acl {logger}{delivery}} + dbl_host_defer_query = ${acl {logger}{deferral}} + +# End diff --git a/test/log/5700 b/test/log/5700 new file mode 100644 index 000000000..edfb932b0 --- /dev/null +++ b/test/log/5700 @@ -0,0 +1,19 @@ +1999-03-02 09:44:33 10HmaX-0005vi-00 <= CALLER@the.local.host.name U=CALLER P=local S=sss +1999-03-02 09:44:33 Start queue run: pid=pppp -qqf +1999-03-02 09:44:33 10HmaX-0005vi-00 => userx@domain1 R=others T=smtp H=127.0.0.1 [127.0.0.1] C="250 OK" +1999-03-02 09:44:33 10HmaX-0005vi-00 delivery ip <127.0.0.1> port <1224> fqdn <127.0.0.1> local_part domain confirmation <250 OK> errno <0> errstr <> router transport +1999-03-02 09:44:33 10HmaX-0005vi-00 Completed +1999-03-02 09:44:33 End queue run: pid=pppp -qqf +1999-03-02 09:44:33 10HmaY-0005vi-00 <= CALLER@the.local.host.name U=CALLER P=local S=sss +1999-03-02 09:44:33 10HmaY-0005vi-00 SMTP timeout while connected to 127.0.0.1 [127.0.0.1] after EHLO the.local.host.name: Connection timed out +1999-03-02 09:44:33 10HmaY-0005vi-00 deferral ip <127.0.0.1> port <1224> fqdn <127.0.0.1> local_part domain confirmation <> errno <110> errstr router transport +1999-03-02 09:44:33 10HmaY-0005vi-00 == userx@domain1.com R=others T=smtp defer (dd): Connection timed out: SMTP timeout while connected to 127.0.0.1 [127.0.0.1] after EHLO the.local.host.name +1999-03-02 09:44:33 10HmaY-0005vi-00 ** userx@domain1.com: retry timeout exceeded +1999-03-02 09:44:33 10HmaZ-0005vi-00 <= <> R=10HmaY-0005vi-00 U=EXIMUSER P=local S=sss +1999-03-02 09:44:33 10HmaZ-0005vi-00 SMTP timeout while connected to 127.0.0.1 [127.0.0.1] after initial connection: Connection timed out +1999-03-02 09:44:33 10HmaZ-0005vi-00 deferral ip <127.0.0.1> port <1224> fqdn <127.0.0.1> local_part domain confirmation <> errno <110> errstr router transport +1999-03-02 09:44:33 10HmaZ-0005vi-00 == CALLER@the.local.host.name R=others T=smtp defer (dd): Connection timed out: SMTP timeout while connected to 127.0.0.1 [127.0.0.1] after initial connection +1999-03-02 09:44:33 10HmaZ-0005vi-00 ** CALLER@the.local.host.name: retry timeout exceeded +1999-03-02 09:44:33 10HmaZ-0005vi-00 CALLER@the.local.host.name: error ignored +1999-03-02 09:44:33 10HmaZ-0005vi-00 Completed +1999-03-02 09:44:33 10HmaY-0005vi-00 Completed diff --git a/test/scripts/5700-deliv-log/5700 b/test/scripts/5700-deliv-log/5700 new file mode 100644 index 000000000..dccf02ca5 --- /dev/null +++ b/test/scripts/5700-deliv-log/5700 @@ -0,0 +1,39 @@ +# Arbtirary expansion after transport +# (EXPERIMENTAL_BDL - database logging) +# +need_ipv4 +# +exim -odq userx@domain1 +A deliverable message +**** +server PORT_S +220 ESMTP +EHLO +250-OK +250 HELP +MAIL +250 OK +RCPT +250 OK +DATA +354 More... +. +250 OK +QUIT +220 OK +**** +exim -qqf +**** +# +# +# +server PORT_S +220 ESMTP +EHLO +*sleep 4 +**** +exim -odi userx@domain1.com +A message which will hit a timeout +. +**** + diff --git a/test/scripts/5700-deliv-log/REQUIRES b/test/scripts/5700-deliv-log/REQUIRES new file mode 100644 index 000000000..338b5566e --- /dev/null +++ b/test/scripts/5700-deliv-log/REQUIRES @@ -0,0 +1 @@ +support Experimental_DBL diff --git a/test/stdout/5700 b/test/stdout/5700 new file mode 100644 index 000000000..32c3c8948 --- /dev/null +++ b/test/stdout/5700 @@ -0,0 +1,34 @@ + +******** SERVER ******** +Listening on port 1224 ... +Connection request from [127.0.0.1] +220 ESMTP +EHLO the.local.host.name +250-OK +250 HELP +MAIL FROM: +250 OK +RCPT TO: +250 OK +DATA +354 More... +Received: from CALLER by the.local.host.name with local (Exim x.yz) + (envelope-from ) + id 10HmaX-0005vi-00 + for userx@domain1; Tue, 2 Mar 1999 09:44:33 +0000 +Message-Id: +From: CALLER_NAME +Date: Tue, 2 Mar 1999 09:44:33 +0000 + +A deliverable message +. +250 OK +QUIT +220 OK +End of script +Listening on port 1224 ... +Connection request from [127.0.0.1] +220 ESMTP +EHLO the.local.host.name +*sleep 4 +End of script