&` incoming_interface `& local interface on <= and => lines
&` incoming_port `& remote port on <= lines
&`*lost_incoming_connection `& as it says (includes timeouts)
-&` millisec `& millisecond timestamps
+&` millisec `& millisecond timestamps and QT/DT times
&` outgoing_interface `& local interface on => lines
&` outgoing_port `& add remote port to => lines
&`*queue_run `& start and end queue runs
.cindex "log" "delivery duration"
&%deliver_time%&: For each delivery, the amount of real time it has taken to
perform the actual delivery is logged as DT=<&'time'&>, for example, &`DT=1s`&.
+If millisecond logging is enabled, short times will be shown with greater
+precision, eg. &`DT=0.304`&.
.next
.cindex "log" "message size on delivery"
.cindex "size" "of message"
This means that it may be longer than the difference between the arrival and
delivery log line times, because the arrival log line is not written until the
message has been successfully received.
+If millisecond logging is enabled, short times will be shown with greater
+precision, eg. &`QT=1.578s`&.
.next
&%queue_time_overall%&: The amount of time the message has been in the queue on
the local host is logged as QT=<&'time'&> on &"Completed"& lines, for
int received_count = 0;
uschar *received_protocol = NULL;
-int received_time = 0;
+struct timeval received_time = { 0, 0 };
int recipients_count = 0;
recipient_item *recipients_list = NULL;
int recipients_list_max = 0;
else
{
- q->update_time = q->input_time = received_time;
+ q->update_time = q->input_time = received_time.tv_sec;
if ((p = strstric(sender_address+1, qualify_domain, FALSE)) != NULL &&
*(--p) == '@') *p = 0;
}
addr2->transport_return = addr->transport_return;
addr2->basic_errno = addr->basic_errno;
addr2->more_errno = addr->more_errno;
+ addr2->delivery_usec = addr->delivery_usec;
addr2->special_action = addr->special_action;
addr2->message = addr->message;
addr2->user_message = addr->user_message;
}
+
+void
+timesince(struct timeval * diff, struct timeval * then)
+{
+gettimeofday(diff, NULL);
+diff->tv_sec -= then->tv_sec;
+if ((diff->tv_usec -= then->tv_usec) < 0)
+ {
+ diff->tv_sec--;
+ diff->tv_usec += 1000*1000;
+ }
+}
+
+
+
+static uschar *
+string_timediff(struct timeval * diff)
+{
+static uschar buf[sizeof("0.000s")];
+
+if (diff->tv_sec >= 5 || !LOGGING(millisec))
+ return readconf_printtime((int)diff->tv_sec);
+
+sprintf(CS buf, "%d.%03ds", (int)diff->tv_sec, (int)diff->tv_usec/1000);
+return buf;
+}
+
+
+static uschar *
+string_timesince(struct timeval * then)
+{
+struct timeval diff;
+
+timesince(&diff, then);
+return string_timediff(&diff);
+}
+
/******************************************************************************/
if (LOGGING(queue_time))
s = string_append(s, &size, &ptr, 2, US" QT=",
- readconf_printtime( (int) ((long)time(NULL) - (long)received_time)) );
+ string_timesince(&received_time));
if (LOGGING(deliver_time))
- s = string_append(s, &size, &ptr, 2, US" DT=",
- readconf_printtime(addr->more_errno));
+ {
+ struct timeval diff = {addr->more_errno, addr->delivery_usec};
+ s = string_append(s, &size, &ptr, 2, US" DT=", string_timediff(&diff));
+ }
/* string_cat() always leaves room for the terminator. Release the
store we used to build the line after writing it. */
|| (ret = write(pfd[pipe_write], &addr2->flags, sizeof(addr2->flags))) != sizeof(addr2->flags)
|| (ret = write(pfd[pipe_write], &addr2->basic_errno, sizeof(int))) != sizeof(int)
|| (ret = write(pfd[pipe_write], &addr2->more_errno, sizeof(int))) != sizeof(int)
+ || (ret = write(pfd[pipe_write], &addr2->delivery_usec, sizeof(int))) != sizeof(int)
|| (ret = write(pfd[pipe_write], &addr2->special_action, sizeof(int))) != sizeof(int)
|| (ret = write(pfd[pipe_write], &addr2->transport,
sizeof(transport_instance *))) != sizeof(transport_instance *)
len = read(pfd[pipe_read], &addr2->flags, sizeof(addr2->flags));
len = read(pfd[pipe_read], &addr2->basic_errno, sizeof(int));
len = read(pfd[pipe_read], &addr2->more_errno, sizeof(int));
+ len = read(pfd[pipe_read], &addr2->delivery_usec, sizeof(int));
len = read(pfd[pipe_read], &addr2->special_action, sizeof(int));
len = read(pfd[pipe_read], &addr2->transport,
sizeof(transport_instance *));
while (addr_local)
{
- time_t delivery_start;
- int deliver_time;
+ struct timeval delivery_start;
+ struct timeval deliver_time;
address_item *addr2, *addr3, *nextaddr;
int logflags = LOG_MAIN;
int logchar = dont_deliver? '*' : '=';
single delivery. */
deliver_set_expansions(addr);
- delivery_start = time(NULL);
+
+ gettimeofday(&delivery_start, NULL);
deliver_local(addr, FALSE);
- deliver_time = (int)(time(NULL) - delivery_start);
+ timesince(&deliver_time, &delivery_start);
/* If a shadow transport (which must perforce be another local transport), is
defined, and its condition is met, we must pass the message to the shadow
/* Done with this address */
- if (result == OK) addr2->more_errno = deliver_time;
+ if (result == OK)
+ {
+ addr2->more_errno = deliver_time.tv_sec;
+ addr2->delivery_usec = deliver_time.tv_usec;
+ }
post_process_one(addr2, result, logflags, DTYPE_TRANSPORT, logchar);
/* If a pipe delivery generated text to be sent back, the result may be
r->flags = *ptr++;
r->key = string_copy(ptr);
while (*ptr++);
- memcpy(&(r->basic_errno), ptr, sizeof(r->basic_errno));
+ memcpy(&r->basic_errno, ptr, sizeof(r->basic_errno));
ptr += sizeof(r->basic_errno);
- memcpy(&(r->more_errno), ptr, sizeof(r->more_errno));
+ memcpy(&r->more_errno, ptr, sizeof(r->more_errno));
ptr += sizeof(r->more_errno);
r->message = *ptr ? string_copy(ptr) : NULL;
DEBUG(D_deliver|D_retry) debug_printf(" added %s item\n",
DEBUG(D_deliver) debug_printf("A0 %s tret %d\n", addr->address, *ptr);
addr->transport_return = *ptr++;
addr->special_action = *ptr++;
- memcpy(&(addr->basic_errno), ptr, sizeof(addr->basic_errno));
+ memcpy(&addr->basic_errno, ptr, sizeof(addr->basic_errno));
ptr += sizeof(addr->basic_errno);
- memcpy(&(addr->more_errno), ptr, sizeof(addr->more_errno));
+ memcpy(&addr->more_errno, ptr, sizeof(addr->more_errno));
ptr += sizeof(addr->more_errno);
- memcpy(&(addr->flags), ptr, sizeof(addr->flags));
+ memcpy(&addr->delivery_usec, ptr, sizeof(addr->delivery_usec));
+ ptr += sizeof(addr->delivery_usec);
+ memcpy(&addr->flags, ptr, sizeof(addr->flags));
ptr += sizeof(addr->flags);
addr->message = *ptr ? string_copy(ptr) : NULL;
while(*ptr++);
{
sprintf(CS big_buffer, "%c%.500s", r->flags, r->key);
ptr = big_buffer + Ustrlen(big_buffer+2) + 3;
- memcpy(ptr, &(r->basic_errno), sizeof(r->basic_errno));
+ memcpy(ptr, &r->basic_errno, sizeof(r->basic_errno));
ptr += sizeof(r->basic_errno);
- memcpy(ptr, &(r->more_errno), sizeof(r->more_errno));
+ memcpy(ptr, &r->more_errno, sizeof(r->more_errno));
ptr += sizeof(r->more_errno);
if (!r->message) *ptr++ = 0; else
{
sprintf(CS big_buffer, "%c%c", addr->transport_return, addr->special_action);
ptr = big_buffer + 2;
- memcpy(ptr, &(addr->basic_errno), sizeof(addr->basic_errno));
+ memcpy(ptr, &addr->basic_errno, sizeof(addr->basic_errno));
ptr += sizeof(addr->basic_errno);
- memcpy(ptr, &(addr->more_errno), sizeof(addr->more_errno));
+ memcpy(ptr, &addr->more_errno, sizeof(addr->more_errno));
ptr += sizeof(addr->more_errno);
- memcpy(ptr, &(addr->flags), sizeof(addr->flags));
+ memcpy(ptr, &addr->delivery_usec, sizeof(addr->delivery_usec));
+ ptr += sizeof(addr->delivery_usec);
+ memcpy(ptr, &addr->flags, sizeof(addr->flags));
ptr += sizeof(addr->flags);
if (!addr->message) *ptr++ = 0; else
{
ptr += sprintf(CS ptr, "%.256s", addr->host_used->name) + 1;
ptr += sprintf(CS ptr, "%.64s", addr->host_used->address) + 1;
- memcpy(ptr, &(addr->host_used->port), sizeof(addr->host_used->port));
+ memcpy(ptr, &addr->host_used->port, sizeof(addr->host_used->port));
ptr += sizeof(addr->host_used->port);
/* DNS lookup status */
if (rc != spool_read_hdrerror)
{
- received_time = 0;
+ received_time.tv_sec = received_time.tv_usec = 0;
+ /*XXX subsec precision?*/
for (i = 0; i < 6; i++)
- received_time = received_time * BASE_62 + tab62[id[i] - '0'];
+ received_time.tv_sec = received_time.tv_sec * BASE_62 + tab62[id[i] - '0'];
}
/* If we've had this malformed message too long, sling it. */
- if (now - received_time > keep_malformed)
+ if (now - received_time.tv_sec > keep_malformed)
{
Uunlink(spool_fname(US"msglog", message_subdir, id, US""));
Uunlink(spool_fname(US"input", message_subdir, id, US"-D"));
if (rc != 0)
{
uschar *s = US"";
- if (now - received_time < retry_maximum_timeout && !addr_defer)
+ if (now - received_time.tv_sec < retry_maximum_timeout && !addr_defer)
{
addr_defer = (address_item *)(+1);
deliver_freeze = TRUE;
if (LOGGING(queue_time_overall))
log_write(0, LOG_MAIN, "Completed QT=%s",
- readconf_printtime( (int) ((long)time(NULL) - (long)received_time)) );
+ string_timesince(&received_time));
else
log_write(0, LOG_MAIN, "Completed");
{
int count;
int show_time;
- int queue_time = time(NULL) - received_time;
+ int queue_time = time(NULL) - received_time.tv_sec;
/* When running in the test harness, there's an option that allows us to
fudge this time so as to get repeatability of the tests. Take the first
Returns: -1, 0, or +1
*/
-int
+static int
exim_tvcmp(struct timeval *t1, struct timeval *t2)
{
if (t1->tv_sec > t2->tv_sec) return +1;
}
}
- yield = retry_find_config(s1, s2, basic_errno, more_errno);
- if (yield == NULL) printf("No retry information found\n"); else
+ if (!(yield = retry_find_config(s1, s2, basic_errno, more_errno)))
+ printf("No retry information found\n");
+ else
{
retry_rule *r;
more_errno = yield->more_errno;
printf("auth_failed ");
else printf("* ");
- for (r = yield->rules; r != NULL; r = r->next)
+ for (r = yield->rules; r; r = r->next)
{
printf("%c,%s", r->rule, readconf_printtime(r->timeout)); /* Do not */
printf(",%s", readconf_printtime(r->p1)); /* amalgamate */
{ "received_ip_address", vtype_stringptr, &interface_address },
{ "received_port", vtype_int, &interface_port },
{ "received_protocol", vtype_stringptr, &received_protocol },
- { "received_time", vtype_int, &received_time },
+ { "received_time", vtype_int, &received_time.tv_sec },
{ "recipient_data", vtype_stringptr, &recipient_data },
{ "recipient_verify_failure",vtype_stringptr,&recipient_verify_failure },
{ "recipients", vtype_string_func, &fn_recipients },
/* If value2 is unset, just compute one number */
if (value2 < 0)
- {
s = string_sprintf("%d", total % value1);
- }
/* Otherwise do a div/mod hash */
extern void exim_exit(int);
extern void exim_nullstd(void);
extern void exim_setugid(uid_t, gid_t, BOOL, uschar *);
-extern int exim_tvcmp(struct timeval *, struct timeval *);
extern void exim_wait_tick(struct timeval *, int);
extern int exp_bool(address_item *addr,
uschar *mtype, uschar *mname, unsigned dgb_opt, uschar *oname, BOOL bvalue,
extern int strncmpic(const uschar *, const uschar *, int);
extern uschar *strstric(uschar *, uschar *, BOOL);
+extern void timesince(struct timeval * diff, struct timeval * then);
+extern void tls_modify_variables(tls_support *);
extern uschar *tod_stamp(int);
-extern void tls_modify_variables(tls_support *);
extern BOOL transport_check_waiting(const uschar *, const uschar *, int, uschar *,
BOOL *, oicf, void*);
extern void transport_init(void);
{ 0 }, /* localpart_cache - ditto */
-1, /* mode */
0, /* more_errno */
+ 0, /* delivery_usec */
ERRNO_UNKNOWNERROR, /* basic_errno */
0, /* child_count */
-1, /* return_file */
int received_headers_max = 30;
uschar *received_protocol = NULL;
-int received_time = 0;
+struct timeval received_time = { 0, 0 };
uschar *recipient_data = NULL;
uschar *recipient_unqualified_hosts = NULL;
uschar *recipient_verify_failure = NULL;
extern uschar *received_for; /* For "for" field */
extern uschar *received_header_text; /* Definition of Received: header */
extern int received_headers_max; /* Max count of Received: headers */
-extern int received_time; /* Time the message was received */
+extern struct timeval received_time; /* Time the message was received */
extern uschar *recipient_data; /* lookup data for recipients */
extern uschar *recipient_unqualified_hosts; /* Permitted unqualified recipients */
extern uschar *recipient_verify_failure; /* What went wrong */
if (Ustat(fname, &statbuf) == 0)
size = message_size + statbuf.st_size - SPOOL_DATA_START_OFFSET + 1;
- i = (now - received_time)/60; /* minutes on queue */
+ i = (now - received_time.tv_sec)/60; /* minutes on queue */
if (i > 90)
{
i = (i + 30)/60;
d = t % 7;
w = t/7;
-if (w > 0) { sprintf(CS p, "%dw", w); while (*p) p++; }
-if (d > 0) { sprintf(CS p, "%dd", d); while (*p) p++; }
-if (h > 0) { sprintf(CS p, "%dh", h); while (*p) p++; }
-if (m > 0) { sprintf(CS p, "%dm", m); while (*p) p++; }
+if (w > 0) p += sprintf(CS p, "%dw", w);
+if (d > 0) p += sprintf(CS p, "%dd", d);
+if (h > 0) p += sprintf(CS p, "%dh", h);
+if (m > 0) p += sprintf(CS p, "%dm", m);
if (s > 0 || p == time_buffer) sprintf(CS p, "%ds", s);
return time_buffer;
/* For other uses of the received time we can operate with granularity of one
second, and for that we use the global variable received_time. This is for
-things like ultimate message timeouts. */
+things like ultimate message timeouts.XXX */
-received_time = message_id_tv.tv_sec;
+received_time = message_id_tv;
/* If SMTP input, set the special handler for timeouts. The alarm() calls
happen in the smtp_getc() function when it refills its buffer. */
last_rule = last_rule->next);
DEBUG(D_retry)
debug_printf(" received_time=%d diff=%d timeout=%d\n",
- received_time, (int)(now - received_time), last_rule->timeout);
- address_timeout = (now - received_time > last_rule->timeout);
+ received_time.tv_sec, (int)(now - received_time.tv_sec), last_rule->timeout);
+ address_timeout = (now - received_time.tv_sec > last_rule->timeout);
}
else
{
this is a small bit of code, and it does no harm to leave it in place,
just in case. */
- if ( received_time <= retry_record->first_failed
+ if ( received_time.tv_sec <= retry_record->first_failed
&& addr == endaddr
&& !retry_record->expired
&& rule)
retry_rule *last_rule;
for (last_rule = rule; last_rule->next; last_rule = last_rule->next)
;
- if (now - received_time > last_rule->timeout)
+ if (now - received_time.tv_sec > last_rule->timeout)
{
DEBUG(D_retry) debug_printf("on queue longer than maximum retry\n");
timedout_count++;
/* time */
if (Ufgets(big_buffer, big_buffer_size, f) == NULL) goto SPOOL_READ_ERROR;
-if (sscanf(CS big_buffer, "%d %d", &received_time, &warning_count) != 2)
+if (sscanf(CS big_buffer, TIME_T_FMT " %d", &received_time.tv_sec, &warning_count) != 2)
goto SPOOL_FORMAT_ERROR;
+received_time.tv_usec = 0;
-message_age = time(NULL) - received_time;
+message_age = time(NULL) - received_time.tv_sec;
#ifndef COMPILE_UTILITY
DEBUG(D_deliver) debug_printf("user=%s uid=%ld gid=%ld sender=%s\n",
break;
case 'l':
- if (Ustrcmp(p, "ocal") == 0) sender_local = TRUE;
+ if (Ustrcmp(p, "ocal") == 0)
+ sender_local = TRUE;
else if (Ustrcmp(big_buffer, "-localerror") == 0)
local_error_message = TRUE;
else if (Ustrncmp(p, "ocal_scan ", 10) == 0)
case 'r':
if (Ustrncmp(p, "eceived_protocol", 16) == 0)
received_protocol = string_copy(big_buffer + 19);
+ else if (Ustrncmp(p, "eceived_time_usec", 17) == 0)
+ {
+ unsigned usec;
+ if (sscanf(CS big_buffer + 21, "%u", &usec) == 1)
+ received_time.tv_usec = usec;
+ }
break;
case 's':
fprintf(f, "%.63s %ld %ld\n", originator_login, (long int)originator_uid,
(long int)originator_gid);
fprintf(f, "<%s>\n", sender_address);
-fprintf(f, "%d %d\n", received_time, warning_count);
+fprintf(f, "%d %d\n", received_time.tv_sec, warning_count);
+
+fprintf(f, "-received_time_usec .%06d\n", received_time.tv_usec);
/* If there is information about a sending host, remember it. The HELO
data can be set for local SMTP as well as remote. */
-if (sender_helo_name != NULL)
+if (sender_helo_name)
fprintf(f, "-helo_name %s\n", sender_helo_name);
-if (sender_host_address != NULL)
+if (sender_host_address)
{
fprintf(f, "-host_address %s.%d\n", sender_host_address, sender_host_port);
- if (sender_host_name != NULL)
+ if (sender_host_name)
fprintf(f, "-host_name %s\n", sender_host_name);
- if (sender_host_authenticated != NULL)
+ if (sender_host_authenticated)
fprintf(f, "-host_auth %s\n", sender_host_authenticated);
}
/* Also about the interface a message came in on */
-if (interface_address != NULL)
+if (interface_address)
fprintf(f, "-interface_address %s.%d\n", interface_address, interface_port);
if (smtp_active_hostname != primary_hostname)
likely to be the same as originator_login, but will be different if
the originator was root, forcing a different ident. */
-if (sender_ident != NULL) fprintf(f, "-ident %s\n", sender_ident);
+if (sender_ident) fprintf(f, "-ident %s\n", sender_ident);
/* Ditto for the received protocol */
-if (received_protocol != NULL)
+if (received_protocol)
fprintf(f, "-received_protocol %s\n", received_protocol);
/* Preserve any ACL variables that are set. */
if (body_zerocount > 0) fprintf(f, "-body_zerocount %d\n", body_zerocount);
-if (authenticated_id != NULL)
+if (authenticated_id)
fprintf(f, "-auth_id %s\n", authenticated_id);
-if (authenticated_sender != NULL)
+if (authenticated_sender)
fprintf(f, "-auth_sender %s\n", authenticated_sender);
if (allow_unqualified_recipient) fprintf(f, "-allow_unqualified_recipient\n");
/* Write the dsn flags to the spool header file */
DEBUG(D_deliver) debug_printf("DSN: Write SPOOL :-dsn_envid %s\n", dsn_envid);
-if (dsn_envid != NULL) fprintf(f, "-dsn_envid %s\n", dsn_envid);
+if (dsn_envid) fprintf(f, "-dsn_envid %s\n", dsn_envid);
DEBUG(D_deliver) debug_printf("DSN: Write SPOOL :-dsn_ret %d\n", dsn_ret);
if (dsn_ret != 0) fprintf(f, "-dsn_ret %d\n", dsn_ret);
These are saved as a record for debugging. Don't included them in the message's
size. */
-for (h = header_list; h != NULL; h = h->next)
+for (h = header_list; h; h = h->next)
{
fprintf(f, "%03d%c %s", h->slen, h->type, h->text);
size_correction += 5;
int mode; /* mode for local transporting to a file */
int more_errno; /* additional error information */
/* (may need to hold a timestamp) */
+ unsigned int delivery_usec; /* subsecond part of delivery time */
short int basic_errno; /* status after failure */
unsigned short child_count; /* number of child addresses */
!= sizeof(int)
|| write(pfd[pipe_write], (void *)&tctx->addr->more_errno, sizeof(int))
!= sizeof(int)
+ || write(pfd[pipe_write], (void *)&tctx->addr->delivery_usec, sizeof(int))
+ != sizeof(int)
)
rc = FALSE; /* compiler quietening */
_exit(0);
else if (!ok)
{
int dummy = read(pfd[pipe_read], (void *)&save_errno, sizeof(int));
- dummy = read(pfd[pipe_read], (void *)&(tctx->addr->more_errno), sizeof(int));
+ dummy = read(pfd[pipe_read], (void *)&tctx->addr->more_errno, sizeof(int));
+ dummy = read(pfd[pipe_read], (void *)&tctx->addr->delivery_usec, sizeof(int));
yield = FALSE;
}
}
int yield = OK;
int save_errno;
int rc;
-time_t start_delivery_time = time(NULL);
+struct timeval start_delivery_time;
BOOL pass_message = FALSE;
uschar *message = NULL;
smtp_context sx;
+gettimeofday(&start_delivery_time, NULL);
suppress_tls = suppress_tls; /* stop compiler warning when no TLS support */
*message_defer = FALSE;
if (sx.ok)
{
int flag = '=';
- int delivery_time = (int)(time(NULL) - start_delivery_time);
+ struct timeval delivery_time;
int len;
- uschar *conf = NULL;
+ uschar * conf = NULL;
+ timesince(&delivery_time, &start_delivery_time);
sx.send_rset = FALSE;
pipelining_active = FALSE;
actual host that was used. */
addr->transport_return = OK;
- addr->more_errno = delivery_time;
+ addr->more_errno = delivery_time.tv_sec;
+ addr->delivery_usec = delivery_time.tv_usec;
addr->host_used = host;
addr->special_action = flag;
addr->message = conf;
{
if ( !host->address
|| host->status != hstatus_unusable_expired
- || host->last_try > received_time)
+ || host->last_try > received_time.tv_sec)
continue;
DEBUG(D_transport) debug_printf("trying expired host %s [%s]%s\n",
host->name, host->address, pistring);
for (last_rule = retry->rules;
last_rule->next;
last_rule = last_rule->next);
- timedout = time(NULL) - received_time > last_rule->timeout;
+ timedout = time(NULL) - received_time.tv_sec > last_rule->timeout;
}
else timedout = TRUE; /* No rule => timed out */
1999-03-02 09:44:33 10HmaX-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
1999-03-02 09:44:33 10HmaX-0005vi-00 => discarded <exim-filter@test.ex> R=r1
1999-03-02 09:44:33 10HmaX-0005vi-00 => discarded <sieve-filter@test.ex> R=r1
-1999-03-02 09:44:33 10HmaX-0005vi-00 Completed QT=0s
+1999-03-02 09:44:33 10HmaX-0005vi-00 Completed QT=qqs
1999-03-02 09:44:33 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
1999-03-02 09:44:33 10HmaY-0005vi-00 => discarded <exim-filter@test.ex> R=r1
1999-03-02 09:44:33 10HmaY-0005vi-00 == sieve-filter@test.ex R=r1 defer (-17): error in filter file: Sieve filtering not enabled
1999-03-02 09:44:33 [1235] 10HmaX-0005vi-00 => usery <usery@test.ex> R=r1 T=t1
1999-03-02 09:44:33 [1235] 10HmaX-0005vi-00 Completed
1999-03-02 09:44:33 [1236] 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userx <userx@test.ex> R=r1 T=t1
-1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz <userz@test.ex> R=r1 T=t1
+1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userx <userx@test.ex> R=r1 T=t1 QT=qqs
+1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz <userz@test.ex> R=r1 T=t1 QT=qqs
1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 Completed
2017-07-30 18:51:05.712 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => userx <userx@test.ex> R=r1 T=t1
-2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => userx <userx@test.ex> R=r1 T=t1 QT=q.qqqs DT=q.qqqs
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed QT=q.qqqs
s/^\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d\.\d{3}(\s[+-]\d\d\d\d)?\s/2017-07-30 18:51:05.712 /gx;
s/^Logwrite\s"\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d/Logwrite "1999-03-02 09:44:33/gx;
+ s/([QD]T=)\d+s/$1qqs/g;
+ s/([QD]T=)\d\.\d{3}s/$1q.qqqs/g;
+
# Date/time in message separators
s/(?:[A-Z][a-z]{2}\s){2}\d\d\s\d\d:\d\d:\d\d\s\d\d\d\d
/Tue Mar 02 09:44:33 1999/gx;
# Date/time in exim -bV output
s/\d\d-[A-Z][a-z]{2}-\d{4}\s\d\d:\d\d:\d\d/07-Mar-2000 12:21:52/g;
- # Time on queue tolerance
- s/(QT|D)=1s/$1=0s/;
-
# Eximstats heading
s/Exim\sstatistics\sfrom\s\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d\sto\s
\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d/Exim statistics from <time> to <time>/x;
# optional IDN2 variant conversions. Accept either IDN1 or IDN2
s/conversion strasse.de/conversion xn--strae-oqa.de/;
s/conversion: german.xn--strae-oqa.de/conversion: german.straße.de/;
+
+ # subsecond timstamp info in reported header-files
+ s/^(-received_time_usec \.)\d{6}$/$1uuuuuu/;
}
# ======== stderr ========
exim -odi userx@test.ex usery@test.ex
Message 1
****
-exim -odi userx@test.ex userz@test.ex
+exim -DLOG_SELECTOR=+pid+queue_time -odi userx@test.ex userz@test.ex
Message 2
****
-exim -DLOG_SELECTOR=+millisec -odi userx@test.ex
+exim -DLOG_SELECTOR=+queue_time+queue_time_overall+deliver_time+millisec -odi userx@test.ex
Message 3
****
exigrep userx
EXIMUSER EXIM_UID EXIM_GID
<notsubmit@y>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
EXIMUSER EXIM_UID EXIM_GID
<a@y>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
EXIMUSER EXIM_UID EXIM_GID
<>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
EXIMUSER EXIM_UID EXIM_GID
<notsubmit@y>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
EXIMUSER EXIM_UID EXIM_GID
<a@y>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
EXIMUSER EXIM_UID EXIM_GID
<a@y>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
EXIMUSER EXIM_UID EXIM_GID
<a@y>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 1
CALLER UID GID
<CALLER-rewritten@test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER-rewritten@test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER-rewritten@test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER@test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local-smtp
-aclm 0 22
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local-smtp
-body_linecount 0
CALLER UID GID
<CALLER@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident CALLER
-received_protocol local-smtp
-body_linecount 2
CALLER UID GID
<"spaced user"@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-ident spaced user
-received_protocol local
-body_linecount 1
1999-03-02 09:44:33 [1235] 10HmaX-0005vi-00 Completed
1999-03-02 09:44:33 [1236] 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userx <userx@test.ex> R=r1 T=t1
-1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz <userz@test.ex> R=r1 T=t1
+1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userx <userx@test.ex> R=r1 T=t1 QT=qqs
+1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz <userz@test.ex> R=r1 T=t1 QT=qqs
1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 Completed
2017-07-30 18:51:05.712 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => userx <userx@test.ex> R=r1 T=t1
-2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => userx <userx@test.ex> R=r1 T=t1 QT=q.qqqs DT=q.qqqs
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed QT=q.qqqs
exigrep exit code = 0
EXIMUSER EXIM_UID EXIM_GID
<username@myhost.test.ex>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-host_auth au1
EXIMUSER EXIM_UID EXIM_GID
<>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-host_auth au1
EXIMUSER EXIM_UID EXIM_GID
<>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-host_auth au1
EXIMUSER EXIM_UID EXIM_GID
<>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-host_auth au1
EXIMUSER EXIM_UID EXIM_GID
<>
ddddddddd 0
+-received_time_usec .uuuuuu
-helo_name rhu.barb
-host_address 127.0.0.1.9999
-host_auth au1
git://git.exim.org / exim.git / commitdiff