[exim] exim does not execute a a router+transport when it sh…

Top Page
Delete this message
Reply to this message
Author: fBXzK kEl1q
Date:  
To: exim-users
Subject: [exim] exim does not execute a a router+transport when it should execute it
I tried the following with Exim version 4.82 and Exim version 4.75 and it
happened both times. Here is what happens:

In the following I expect the router "todestination1" to be executed (the
attached debug confirms in my opinion that the condition is true):

exim.conf extract:

######################################################################
#                      ROUTERS CONFIGURATION                         #
#               Specifies how addresses are handled                  #
######################################################################
#     THE ORDER IN WHICH THE ROUTERS ARE DEFINED IS IMPORTANT!       #
# An address is passed to each router in turn until it is accepted.  #
######################################################################


begin routers

todestination1:
driver = redirect
local_part_suffix = +*
local_part_suffix_optional
condition = ${if
match{${lookup{${quote_local_part:${sg{$local_part}{\N\+.+$\N}{}}}_T9}lsearch{/etc/exim/table1}{success}{fail}}}{success}
}
data = ${sg
{${lookup{${quote_local_part:$local_part}_T9}lsearch{/etc/exim/table1}{$value}{notfound}}}{\N\+inbox\N}{$local_part_suffix}}
redirect_router = router11
unseen
no_verify

savetodisk:
driver = accept
local_part_suffix = +*
local_part_suffix_optional
transport = buffer_mail
no_verify

router11:
driver = manualroute
hosts_randomize = true
route_data = 10.30.32.41
transport = mytransport11
no_verify


######################################################################
#                      TRANSPORTS CONFIGURATION                      #
######################################################################


begin transports

buffer_mail:
driver = appendfile
directory = "/hwr10pool/data/$local_part/$local_part$local_part_suffix"
directory_file = "${tr{${tod_log}${tod_zone}}{ }{_}}_${inode}.msg"
message_prefix =
check_string =
escape_string =
message_suffix =

mytransport11:
driver = smtp
connection_max_messages = 750
hosts = 10.30.32.41
hosts_randomize = true
hosts_override = true







The file /etc/exim./table1 that is being read has only one line:
example.com_T9:example.com@???


Here is step by step what happens:

mailer log (in this case blat was used for testing):

2015.08.19 10:07:39 (Wed)------------Start of Session-----------------
Blat v3.0.6 (build : Jun 21 2012 23:52:52)
32-bit Windows, Full, Unicode
2015.08.19 10:07:39 (Wed): <<<getline<<< 220 spool1.example.com SMTP
SPOOLER 4.82 Wed, 19 Aug 2015 17:07:39 +0000
2015.08.19 10:07:39 (Wed): >>>putline>>> EHLO desktop1
2015.08.19 10:07:39 (Wed): <<<getline<<< 250-spool1.example.com Hello
desktop1 [10.5.6.13]
2015.08.19 10:07:39 (Wed): <<<getline<<< 250-SIZE 524288000
2015.08.19 10:07:39 (Wed): <<<getline<<< 250-8BITMIME
2015.08.19 10:07:39 (Wed): <<<getline<<< 250-PIPELINING
2015.08.19 10:07:39 (Wed): <<<getline<<< 250-AUTH PLAIN LOGIN
2015.08.19 10:07:39 (Wed): <<<getline<<< 250-STARTTLS
2015.08.19 10:07:39 (Wed): <<<getline<<< 250 HELP
2015.08.19 10:07:39 (Wed): Sending try.msg to example.com@???
2015.08.19 10:07:39 (Wed): Subject: mysubject
2015.08.19 10:07:39 (Wed): Login name is example.com@???
2015.08.19 10:07:39 (Wed): >>>putline>>> MAIL FROM:<example.com@???>
2015.08.19 10:07:39 (Wed): <<<getline<<< 250 OK
2015.08.19 10:07:39 (Wed): >>>putline>>> RCPT TO:<example.com@???>
2015.08.19 10:07:39 (Wed): <<<getline<<< 250 Accepted
2015.08.19 10:07:39 (Wed): >>>putline>>> DATA
2015.08.19 10:07:39 (Wed): <<<getline<<< 354 Enter message, ending with "."
on a line by itself
2015.08.19 10:07:39 (Wed): <<<getline<<< 250 OK id=1ZS6pv-0002iG-QL
2015.08.19 10:07:39 (Wed): >>>putline>>> QUIT
2015.08.19 10:07:39 (Wed): <<<getline<<< 221 spool1.example.com closing
connection
2015.08.19 10:07:39 (Wed)-------------End of Session------------------


/var/log/exim/mainlog:

2015-08-19 17:07:36 cwd=/etc/exim 3 args: exim -bd -d+all
2015-08-19 17:07:36 exim 4.82 daemon started: pid=10430, no queue runs,
listening for SMTP on port 25 (IPv6 and IPv4)
2015-08-19 17:07:39 SMTP connection from [10.5.6.13]:56102
I=[10.21.20.250]:25 (TCP/IP connection count = 1)
2015-08-19 17:07:39 1ZS6pv-0002iG-QL <= example.com@???
H=(desktop1) [10.5.6.13]:56102 I=[10.21.20.250]:25 P=esmtp S=565
id=01d0daa1$Blat.v3.0.6$8dcab766$251c3fa53c59@10.21.20.250 T="mysubject"
from <example.com@???> for example.com@???
2015-08-19 17:07:39 SMTP connection from (desktop1) [10.5.6.13]:56102
I=[10.21.20.250]:25 closed by QUIT
2015-08-19 17:07:39 cwd=/var/spool/exim 4 args: /usr/sbin/exim
-d=0xfffdffff -Mc 1ZS6pv-0002iG-QL
2015-08-19 17:07:39 1ZS6pv-0002iG-QL => example.com <example.com@???>
F=<example.com@???> P=<example.com@???> R=savetodisk
T=buffer_mail S=565 QT=0s DT=0s
2015-08-19 17:07:39 1ZS6pv-0002iG-QL Completed QT=0s


note about the mainlog above: mytransport11 is not in the mainlog but
according to the debug log it should have been executed:
17:07:39 10433 routed by router11 router
17:07:39 10433 envelope to: example.com@???
17:07:39 10433 transport: mytransport11
17:07:39 10433 host 10.30.32.41 [10.30.32.41] rgroup=-2

(see more of the debug log in the attached file)
debug log: debug_log_for_question.txt is attached (created by: exim -bd
-d+all > /tmp/debug_log_for_question.txt 2>&1 )


Does anyone have an idea what may be wrong?

Thanks,
17:07:36 10430 Exim version 4.82 uid=0 gid=0 pid=10430 D=fffdffff
Berkeley DB: Berkeley DB 4.7.25: (April  4, 2012)
Support for: crypteq iconv() IPv6 PAM Perl Expand_dlfunc TCPwrappers OpenSSL Content_Scanning DKIM Old_Demime
Lookups (built-in): lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmjz dbmnz dnsdb dsearch ldap ldapdn ldapm nis nis0 nisplus passwd sqlite
Authenticators: cram_md5 cyrus_sasl dovecot plaintext spa
Routers: accept dnslookup ipliteral manualroute queryprogram redirect
Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
Fixed never_users: 0
Size of off_t: 8
Compiler: GCC [4.4.7 20120313 (Red Hat 4.4.7-3)]
Library version: OpenSSL: Compile: OpenSSL 1.0.1e-fips 11 Feb 2013
                          Runtime: OpenSSL 1.0.1e-fips 11 Feb 2013
Library version: Cyrus SASL: Compile: 2.1.23
                             Runtime: 2.1.23 [Cyrus SASL]
Library version: PCRE: Compile: 7.8
                       Runtime: 7.8 2008-09-05
17:07:36 10430 Loading lookup modules from /usr/lib64/exim/4.82-3.el6/lookups
17:07:36 10430 Loaded 0 lookup modules
17:07:36 10430 Total 18 lookups
Library version: SQLite: Compile: 3.6.20
                         Runtime: 3.6.20
WHITELIST_D_MACROS unset
TRUSTED_CONFIG_LIST: "/etc/exim/trusted-configs"
17:07:36 10430 changed uid/gid: forcing real = effective
17:07:36 10430   uid=0 gid=0 pid=10430
17:07:36 10430   auxiliary group list: <none>
17:07:36 10430 seeking password data for user "root": cache not available
17:07:36 10430 getpwnam() succeeded uid=0 gid=0
17:07:36 10431 changed uid/gid: calling tls_validate_require_cipher
17:07:36 10431   uid=93 gid=93 pid=10431
17:07:36 10431   auxiliary group list: <none>
17:07:36 10430 tls_validate_require_cipher child 10431 ended: status=0x0
17:07:36 10430 openssl option, adding from 1000000: 1000000 (no_sslv2)
17:07:36 10430 openssl option, adding from 1000000: 2000000 (no_sslv3)
17:07:36 10430 configuration file is /etc/exim/exim.conf
17:07:36 10430 log selectors = ffffffbf 7dfffeff
17:07:36 10430 LOG: MAIN
17:07:36 10430   cwd=/etc/exim 3 args: exim -bd -d+all
17:07:36 10430 trusted user
17:07:36 10430 admin user
17:07:36 10430 originator: uid=0 gid=0 login=root name=root
17:07:36 10430 listening on all interfaces (IPv6) port 25
17:07:36 10430 listening on all interfaces (IPv4) port 25
17:07:36 10430 pid written to /var/run/exim.pid
17:07:36 10430 changed uid/gid: running as a daemon
17:07:36 10430   uid=93 gid=93 pid=10430
17:07:36 10430   auxiliary group list: 12 93
17:07:36 10430 LOG: MAIN
17:07:36 10430   exim 4.82 daemon started: pid=10430, no queue runs, listening for SMTP on port 25 (IPv6 and IPv4)
17:07:36 10430 set_process_info: 10430 daemon: no queue runs, listening for SMTP on port 25 (IPv6 and IPv4)
17:07:36 10430 daemon running with uid=93 gid=93 euid=93 egid=93
17:07:36 10430 Listening...
17:07:39 10430 Connection request from 10.5.6.13 port 56102
17:07:39 10430 interface address=10.21.20.250 port=25
17:07:39 10430 LOG: smtp_connection MAIN
17:07:39 10430   SMTP connection from [10.5.6.13]:56102 I=[10.21.20.250]:25 (TCP/IP connection count = 1)
17:07:39 10430 search_tidyup called
17:07:39 10430 1 SMTP accept process running
17:07:39 10430 Listening...
17:07:39 10432 sender_fullhost = [10.5.6.13]:56102
17:07:39 10432 sender_rcvhost = [10.5.6.13] (port=56102)
17:07:39 10432 Process 10432 is handling incoming connection from [10.5.6.13]:56102
17:07:39 10432 host in host_lookup? no (end of list)
17:07:39 10432 set_process_info: 10432 handling incoming connection from [10.5.6.13]:56102 I=[10.21.20.250]:25
17:07:39 10432 host in host_reject_connection? no (option unset)
17:07:39 10432 host in sender_unqualified_hosts? no (option unset)
17:07:39 10432 host in recipient_unqualified_hosts? no (option unset)
17:07:39 10432 host in helo_verify_hosts? no (option unset)
17:07:39 10432 host in helo_try_verify_hosts? no (option unset)
17:07:39 10432 host in helo_accept_junk_hosts? no (option unset)
17:07:39 10432 expanding: $primary_hostname SMTP SPOOLER $version_number $tod_full
17:07:39 10432    result: spool1.example.com SMTP SPOOLER 4.82 Wed, 19 Aug 2015 17:07:39 +0000
17:07:39 10432 SMTP>> 220 spool1.example.com SMTP SPOOLER 4.82 Wed, 19 Aug 2015 17:07:39 +0000
17:07:39 10432 Process 10432 is ready for new message
17:07:39 10432 smtp_setup_msg entered
17:07:39 10432 SMTP<< EHLO desktop1
17:07:39 10432 desktop1 in helo_lookup_domains? no (end of list)
17:07:39 10432 sender_fullhost = (desktop1) [10.5.6.13]:56102
17:07:39 10432 sender_rcvhost = [10.5.6.13] (port=56102 helo=desktop1)
17:07:39 10432 set_process_info: 10432 handling incoming connection from (desktop1) [10.5.6.13]:56102 I=[10.21.20.250]:25
17:07:39 10432 host in pipelining_advertise_hosts? yes (matched "*")
17:07:39 10432 host in auth_advertise_hosts? yes (matched "*")
17:07:39 10432 host in tls_advertise_hosts? yes (matched "*")
17:07:39 10432 SMTP>> 250-spool1.example.com Hello desktop1 [10.5.6.13]
17:07:39 10432 250-SIZE 524288000
17:07:39 10432 250-8BITMIME
17:07:39 10432 250-PIPELINING
17:07:39 10432 250-AUTH PLAIN LOGIN
17:07:39 10432 250-STARTTLS
17:07:39 10432 250 HELP
17:07:39 10432 SMTP<< MAIL FROM:<example.com@???>
17:07:39 10432 SMTP>> 250 OK
17:07:39 10432 SMTP<< RCPT TO:<example.com@???>
17:07:39 10432 using ACL "acl_check_rcpt"
17:07:39 10432 processing "deny"
17:07:39 10432 expanding: $sender_host_address
17:07:39 10432    result: 10.5.6.13
17:07:39 10432 expanding: +theseneedtls
17:07:39 10432    result: +theseneedtls
17:07:39 10432 10.5.6.13 in "10.5.6.133 : 10.5.6.14 : 10.5.6.15"? no (end of list)
17:07:39 10432 10.5.6.13 in "+theseneedtls"? no (end of list)
17:07:39 10432 expanding: $tls_cipher
17:07:39 10432    result: 
17:07:39 10432 skipping: result is not used
17:07:39 10432 expanding: 
17:07:39 10432    result: 
17:07:39 10432 skipping: result is not used
17:07:39 10432 condition: and{ {match_ip{$sender_host_address}{+theseneedtls}} {eq {$tls_cipher}{}} }
17:07:39 10432    result: false
17:07:39 10432 expanding: yes
17:07:39 10432    result: yes
17:07:39 10432 skipping: result is not used
17:07:39 10432 expanding: no
17:07:39 10432    result: no
17:07:39 10432 expanding: ${if and{ {match_ip{$sender_host_address}{+theseneedtls}} {eq {$tls_cipher}{}} }{yes}{no} }
17:07:39 10432    result: no
17:07:39 10432 check condition = ${if and{ {match_ip{$sender_host_address}{+theseneedtls}} {eq {$tls_cipher}{}} }{yes}{no} }
17:07:39 10432                 = no
17:07:39 10432 deny: condition test failed in ACL "acl_check_rcpt"
17:07:39 10432 processing "defer"
17:07:39 10432 check local_parts = ^[./|] : ^.*[@%!] : ^.*/\\.\\./
17:07:39 10432 expanding: ^[./|] : ^.*[@%!] : ^.*/\\.\\./
17:07:39 10432    result: ^[./|] : ^.*[@%!] : ^.*/\.\./
17:07:39 10432 example.com in "^[./|] : ^.*[@%!] : ^.*/\.\./"? no (end of list)
17:07:39 10432 defer: condition test failed in ACL "acl_check_rcpt"
17:07:39 10432 processing "accept"
17:07:39 10432 check local_parts = postmaster
17:07:39 10432 example.com in "postmaster"? no (end of list)
17:07:39 10432 accept: condition test failed in ACL "acl_check_rcpt"
17:07:39 10432 processing "accept"
17:07:39 10432 check hosts = @[] : 10.20.8.45 : 10.20.8.52 : 10.128.45.24 : 127.0.0.1 : ::::1
17:07:39 10432 Actual local interface address is 127.0.0.1 (lo)
17:07:39 10432 Actual local interface address is 10.21.20.250 (eth0)
17:07:39 10432 Actual local interface address is fe80::250:56ff:fe8d:6b2e (eth0)
17:07:39 10432 Actual local interface address is ::1 (lo)
17:07:39 10432 host in "@[] : 10.20.8.45 : 10.20.8.52 : 10.128.45.24 : 127.0.0.1 : ::::1"? no (end of list)
17:07:39 10432 accept: condition test failed in ACL "acl_check_rcpt"
17:07:39 10432 processing "accept"
17:07:39 10432 check hosts = 10.20.8.0/24
17:07:39 10432 host in "10.20.8.0/24"? no (end of list)
17:07:39 10432 accept: condition test failed in ACL "acl_check_rcpt"
17:07:39 10432 processing "accept"
17:07:39 10432 check authenticated = *
17:07:39 10432 accept: condition test failed in ACL "acl_check_rcpt"
17:07:39 10432 processing "accept"
17:07:39 10432 check verify = recipient
17:07:39 10432 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10432 Verifying example.com@???
17:07:39 10432 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10432 Considering example.com@???
17:07:39 10432 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10432 routing example.com@???
17:07:39 10432 --------> todestination1 router <--------
17:07:39 10432 local_part=example.com domain=example.com
17:07:39 10432 todestination1 router skipped: verify 2 0 0
17:07:39 10432 --------> savetodisk router <--------
17:07:39 10432 local_part=example.com domain=example.com
17:07:39 10432 savetodisk router skipped: verify 2 0 0
17:07:39 10432 --------> router11 router <--------
17:07:39 10432 local_part=example.com domain=example.com
17:07:39 10432 router11 router skipped: verify 2 0 0
17:07:39 10432 no more routers
17:07:39 10432 ----------- end verify ------------
17:07:39 10432 accept: condition test failed in ACL "acl_check_rcpt"
17:07:39 10432 processing "accept"
17:07:39 10432 check hosts = 10.5.6.13
17:07:39 10432 host in "10.5.6.13"? yes (matched "10.5.6.13")
17:07:39 10432 accept: condition test succeeded in ACL "acl_check_rcpt"
17:07:39 10432 SMTP>> 250 Accepted
17:07:39 10432 SMTP<< DATA
17:07:39 10432 SMTP>> 354 Enter message, ending with "." on a line by itself
17:07:39 10432 search_tidyup called
PDKIM >> Hashed body data, canonicalized >>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10432 host in ignore_fromline_hosts? no (option unset)
17:07:39 10432 >>Headers received:
17:07:39 10432 Date: Wed, 19 Aug 2015 10:07:39 -0700
17:07:39 10432 From: example.com@???
17:07:39 10432 To: example.com@???
17:07:39 10432 X-Mailer: Blat v3.0.6, a Win32 SMTP/NNTP mailer http://www.blat.net
17:07:39 10432 Message-ID: <01d0daa1$Blat.v3.0.6$8dcab766$251c3fa53c59@10.21.20.250>
17:07:39 10432 Subject: mysubject
17:07:39 10432 Content-Transfer-Encoding: 7BIT
17:07:39 10432 Content-Type: text/plain;
17:07:39 10432  charset="ISO-8859-1"
17:07:39 10432 
17:07:39 10432 rewrite_one_header: type=F:
17:07:39 10432   From: example.com@???
17:07:39 10432 rewrite_one_header: type=T:
17:07:39 10432   To: example.com@???
17:07:39 10432 search_tidyup called
17:07:39 10432 >>Headers after rewriting and local additions:
17:07:39 10432   Date: Wed, 19 Aug 2015 10:07:39 -0700
17:07:39 10432 F From: example.com@???
17:07:39 10432 T To: example.com@???
17:07:39 10432   X-Mailer: Blat v3.0.6, a Win32 SMTP/NNTP mailer http://www.blat.net
17:07:39 10432 I Message-ID: <01d0daa1$Blat.v3.0.6$8dcab766$251c3fa53c59@10.21.20.250>
17:07:39 10432   Subject: mysubject
17:07:39 10432   Content-Transfer-Encoding: 7BIT
17:07:39 10432   Content-Type: text/plain;
17:07:39 10432  charset="ISO-8859-1"
17:07:39 10432 
17:07:39 10432 Data file written for message 1ZS6pv-0002iG-QL
17:07:39 10432 expanding: ${tod_full}
17:07:39 10432    result: Wed, 19 Aug 2015 17:07:39 +0000
17:07:39 10432 condition: def:sender_rcvhost
17:07:39 10432    result: true
17:07:39 10432 expanding: from $sender_rcvhost\n\t
17:07:39 10432    result: from [10.5.6.13] (port=56102 helo=desktop1)
17:07:39 10432     
17:07:39 10432 condition: def:sender_ident
17:07:39 10432    result: false
17:07:39 10432 expanding: from $sender_ident 
17:07:39 10432    result: from  
17:07:39 10432 skipping: result is not used
17:07:39 10432 condition: def:sender_helo_name
17:07:39 10432    result: false
17:07:39 10432 expanding: (helo=$sender_helo_name)\n\t
17:07:39 10432    result: (helo=)
17:07:39 10432     
17:07:39 10432 skipping: result is not used
17:07:39 10432 expanding: ${if def:sender_ident {from $sender_ident }}${if def:sender_helo_name {(helo=$sender_helo_name)\n\t}}
17:07:39 10432    result: 
17:07:39 10432 skipping: result is not used
17:07:39 10432 condition: def:received_protocol
17:07:39 10432    result: true
17:07:39 10432 expanding: with $received_protocol
17:07:39 10432    result: with esmtp
17:07:39 10432 condition: def:tls_cipher
17:07:39 10432    result: false
17:07:39 10432 expanding: ($tls_cipher)\n\t
17:07:39 10432    result: ()
17:07:39 10432     
17:07:39 10432 skipping: result is not used
17:07:39 10432 condition: def:received_for
17:07:39 10432    result: true
17:07:39 10432 expanding: \n\tfor $received_for
17:07:39 10432    result: 
17:07:39 10432     for example.com@???
17:07:39 10432 expanding: Received: ${if def:sender_rcvhost {from $sender_rcvhost\n\t}{${if def:sender_ident {from $sender_ident }}${if def:sender_helo_name {(helo=$sender_helo_name)\n\t}}}}by $primary_hostname ${if def:received_protocol {with $received_protocol}} ${if def:tls_cipher {($tls_cipher)\n\t}}(SMTP SPOOLER $version_number)\n\tid $message_id${if def:received_for {\n\tfor $received_for}}
17:07:39 10432    result: Received: from [10.5.6.13] (port=56102 helo=desktop1)
17:07:39 10432     by spool1.example.com with esmtp (SMTP SPOOLER 4.82)
17:07:39 10432     id 1ZS6pv-0002iG-QL
17:07:39 10432     for example.com@???
17:07:39 10432 >>Generated Received: header line
17:07:39 10432 P Received: from [10.5.6.13] (port=56102 helo=desktop1)
17:07:39 10432     by spool1.example.com with esmtp (SMTP SPOOLER 4.82)
17:07:39 10432     id 1ZS6pv-0002iG-QL
17:07:39 10432     for example.com@???; Wed, 19 Aug 2015 17:07:39 +0000
PDKIM <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:07:39 10432 calling local_scan(); timeout=300
17:07:39 10432 local_scan() returned 0 NULL
17:07:39 10432 expanding: ${tod_full}
17:07:39 10432    result: Wed, 19 Aug 2015 17:07:39 +0000
17:07:39 10432 Writing spool header file
17:07:39 10432 Size of headers = 551
17:07:39 10432 expanding: $h_subject:
17:07:39 10432    result: mysubject
17:07:39 10432 LOG: MAIN
17:07:39 10432   <= example.com@??? H=(desktop1) [10.5.6.13]:56102 I=[10.21.20.250]:25 P=esmtp S=565 id=01d0daa1$Blat.v3.0.6$8dcab766$251c3fa53c59@10.21.20.250 T="mysubject"
17:07:39 10432 SMTP>> 250 OK id=1ZS6pv-0002iG-QL
17:07:39 10432 search_tidyup called
17:07:39 10432 Sender: example.com@???
17:07:39 10432 Recipients:
17:07:39 10432   example.com@???
17:07:39 10432 forked delivery process 10433
17:07:39 10432 Process 10432 is ready for new message
17:07:39 10432 smtp_setup_msg entered
17:07:39 10433 exec /usr/sbin/exim -d=0xfffdffff -Mc 1ZS6pv-0002iG-QL
17:07:39 10432 SMTP<< QUIT
17:07:39 10432 SMTP>> 221 spool1.example.com closing connection
17:07:39 10432 LOG: smtp_connection MAIN
17:07:39 10432   SMTP connection from (desktop1) [10.5.6.13]:56102 I=[10.21.20.250]:25 closed by QUIT
17:07:39 10432 search_tidyup called
17:07:39 10430 child 10432 ended: status=0x0
17:07:39 10430   normal exit, 0
17:07:39 10430 0 SMTP accept processes now running
17:07:39 10430 Listening...
17:07:39 10433 Exim version 4.82 uid=93 gid=93 pid=10433 D=fffdffff
Berkeley DB: Berkeley DB 4.7.25: (April  4, 2012)
Support for: crypteq iconv() IPv6 PAM Perl Expand_dlfunc TCPwrappers OpenSSL Content_Scanning DKIM Old_Demime
Lookups (built-in): lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmjz dbmnz dnsdb dsearch ldap ldapdn ldapm nis nis0 nisplus passwd sqlite
Authenticators: cram_md5 cyrus_sasl dovecot plaintext spa
Routers: accept dnslookup ipliteral manualroute queryprogram redirect
Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
Fixed never_users: 0
Size of off_t: 8
Compiler: GCC [4.4.7 20120313 (Red Hat 4.4.7-3)]
Library version: OpenSSL: Compile: OpenSSL 1.0.1e-fips 11 Feb 2013
                          Runtime: OpenSSL 1.0.1e-fips 11 Feb 2013
Library version: Cyrus SASL: Compile: 2.1.23
                             Runtime: 2.1.23 [Cyrus SASL]
Library version: PCRE: Compile: 7.8
                       Runtime: 7.8 2008-09-05
17:07:39 10433 Loading lookup modules from /usr/lib64/exim/4.82-3.el6/lookups
17:07:39 10433 Loaded 0 lookup modules
17:07:39 10433 Total 18 lookups
Library version: SQLite: Compile: 3.6.20
                         Runtime: 3.6.20
WHITELIST_D_MACROS unset
TRUSTED_CONFIG_LIST: "/etc/exim/trusted-configs"
17:07:39 10433 changed uid/gid: forcing real = effective
17:07:39 10433   uid=0 gid=93 pid=10433
17:07:39 10433   auxiliary group list: <none>
17:07:39 10433 seeking password data for user "root": cache not available
17:07:39 10433 getpwnam() succeeded uid=0 gid=0
17:07:39 10434 changed uid/gid: calling tls_validate_require_cipher
17:07:39 10434   uid=93 gid=93 pid=10434
17:07:39 10434   auxiliary group list: <none>
17:07:39 10433 tls_validate_require_cipher child 10434 ended: status=0x0
17:07:39 10433 openssl option, adding from 1000000: 1000000 (no_sslv2)
17:07:39 10433 openssl option, adding from 1000000: 2000000 (no_sslv3)
17:07:39 10433 configuration file is /etc/exim/exim.conf
17:07:39 10433 log selectors = ffffffbf 7dfffeff
17:07:39 10433 LOG: MAIN
17:07:39 10433   cwd=/var/spool/exim 4 args: /usr/sbin/exim -d=0xfffdffff -Mc 1ZS6pv-0002iG-QL
17:07:39 10433 trusted user
17:07:39 10433 admin user
17:07:39 10433 set_process_info: 10433 delivering specified messages
17:07:39 10433 set_process_info: 10433 delivering 1ZS6pv-0002iG-QL
17:07:39 10433 reading spool file 1ZS6pv-0002iG-QL-H
17:07:39 10433 user=exim uid=93 gid=93 sender=example.com@???
17:07:39 10433 sender_fullhost = (desktop1) [10.5.6.13]:56102
17:07:39 10433 sender_rcvhost = [10.5.6.13] (port=56102 helo=desktop1)
17:07:39 10433 sender_local=0 ident=unset
17:07:39 10433 Non-recipients:
17:07:39 10433 Empty Tree
17:07:39 10433 ---- End of tree ----
17:07:39 10433 recipients_count=1
17:07:39 10433 body_linecount=1 message_linecount=13
17:07:39 10433 Delivery address list:
17:07:39 10433   example.com@??? 
17:07:39 10433 locking /var/spool/exim/db/retry.lockfile
17:07:39 10433 locked /var/spool/exim/db/retry.lockfile
17:07:39 10433 EXIM_DBOPEN(/var/spool/exim/db/retry)
17:07:39 10433 returned from EXIM_DBOPEN
17:07:39 10433 opened hints database /var/spool/exim/db/retry: flags=O_RDONLY
17:07:39 10433 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10433 Considering: example.com@???
17:07:39 10433 unique = example.com@???
17:07:39 10433 dbfn_read: key=R:example.com
17:07:39 10433 dbfn_read: key=R:example.com@???
17:07:39 10433 dbfn_read: key=R:example.com@???:<example.com@???>
17:07:39 10433 no domain retry record
17:07:39 10433 no address retry record
17:07:39 10433 example.com@???: queued for routing
17:07:39 10433 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10433 routing example.com@???
17:07:39 10433 --------> todestination1 router <--------
17:07:39 10433 local_part=example.com domain=example.com
17:07:39 10433 checking "condition"
17:07:39 10433 expanding: NULL
17:07:39 10433    result: NULL
17:07:39 10433 considering bool_lax: NULL
17:07:39 10433 expanding: $local_part
17:07:39 10433    result: example.com
17:07:39 10433 expanding: \N\+.+$\N
17:07:39 10433    result: \+.+$
17:07:39 10433 expanding: 
17:07:39 10433    result: 
17:07:39 10433 expanding: ${sg{$local_part}{\N\+.+$\N}{}}
17:07:39 10433    result: example.com
17:07:39 10433 expanding: ${quote_local_part:${sg{$local_part}{\N\+.+$\N}{}}}_T9
17:07:39 10433    result: example.com_T9
17:07:39 10433 expanding: /etc/exim/table1
17:07:39 10433    result: /etc/exim/table1
17:07:39 10433 search_open: lsearch "/etc/exim/table1"
17:07:39 10433 search_find: file="/etc/exim/table1"
17:07:39 10433   key="example.com_T9" partial=-1 affix=NULL starflags=0
17:07:39 10433 LRU list:
17:07:39 10433   :/etc/exim/table1
17:07:39 10433   End
17:07:39 10433 internal_search_find: file="/etc/exim/table1"
17:07:39 10433   type=lsearch key="example.com_T9"
17:07:39 10433 file lookup required for example.com_T9
17:07:39 10433   in /etc/exim/table1
17:07:39 10433 lookup yielded: example.com@???
17:07:39 10433 expanding: success
17:07:39 10433    result: success
17:07:39 10433 expanding: fail
17:07:39 10433    result: fail
17:07:39 10433 skipping: result is not used
17:07:39 10433 expanding: ${lookup{${quote_local_part:${sg{$local_part}{\N\+.+$\N}{}}}_T9}lsearch{/etc/exim/table1}{success}{fail}}
17:07:39 10433    result: success
17:07:39 10433 expanding: success
17:07:39 10433    result: success
17:07:39 10433 condition: match{${lookup{${quote_local_part:${sg{$local_part}{\N\+.+$\N}{}}}_T9}lsearch{/etc/exim/table1}{success}{fail}}}{success}
17:07:39 10433    result: true
17:07:39 10433 expanding: ${if match{${lookup{${quote_local_part:${sg{$local_part}{\N\+.+$\N}{}}}_T9}lsearch{/etc/exim/table1}{success}{fail}}}{success} }
17:07:39 10433    result: true
17:07:39 10433 considering bool_lax: true
17:07:39 10433 condition: and{{bool_lax{NULL}}{bool_lax{${if match{${lookup{${quote_local_part:${sg{$local_part}{\N\+.+$\N}{}}}_T9}lsearch{/etc/exim/table1}{success}{fail}}}{success} }}}}
17:07:39 10433    result: true
17:07:39 10433 expanding: ${if and{{bool_lax{NULL}}{bool_lax{${if match{${lookup{${quote_local_part:${sg{$local_part}{\N\+.+$\N}{}}}_T9}lsearch{/etc/exim/table1}{success}{fail}}}{success} }}}}}
17:07:39 10433    result: true
17:07:39 10433 calling todestination1 router
17:07:39 10433 rda_interpret (string): ${sg {${lookup{${quote_local_part:$local_part}_T9}lsearch{/etc/exim/table1}{$value}{notfound}}}{\N\+inbox\N}{$local_part_suffix}}
17:07:39 10433 expanding: $local_part
17:07:39 10433    result: example.com
17:07:39 10433 expanding: ${quote_local_part:$local_part}_T9
17:07:39 10433    result: example.com_T9
17:07:39 10433 expanding: /etc/exim/table1
17:07:39 10433    result: /etc/exim/table1
17:07:39 10433 search_open: lsearch "/etc/exim/table1"
17:07:39 10433   cached open
17:07:39 10433 search_find: file="/etc/exim/table1"
17:07:39 10433   key="example.com_T9" partial=-1 affix=NULL starflags=0
17:07:39 10433 LRU list:
17:07:39 10433   :/etc/exim/table1
17:07:39 10433   End
17:07:39 10433 internal_search_find: file="/etc/exim/table1"
17:07:39 10433   type=lsearch key="example.com_T9"
17:07:39 10433 cached data used for lookup of example.com_T9
17:07:39 10433   in /etc/exim/table1
17:07:39 10433 lookup yielded: example.com@???
17:07:39 10433 expanding: $value
17:07:39 10433    result: example.com@???
17:07:39 10433 expanding: notfound
17:07:39 10433    result: notfound
17:07:39 10433 skipping: result is not used
17:07:39 10433 expanding: ${lookup{${quote_local_part:$local_part}_T9}lsearch{/etc/exim/table1}{$value}{notfound}}
17:07:39 10433    result: example.com@???
17:07:39 10433 expanding: \N\+inbox\N
17:07:39 10433    result: \+inbox
17:07:39 10433 expanding: $local_part_suffix
17:07:39 10433    result: 
17:07:39 10433 expanding: ${sg {${lookup{${quote_local_part:$local_part}_T9}lsearch{/etc/exim/table1}{$value}{notfound}}}{\N\+inbox\N}{$local_part_suffix}}
17:07:39 10433    result: example.com@???
17:07:39 10433 expanded: example.com@???
17:07:39 10433 file is not a filter file
17:07:39 10433 parse_forward_list: example.com@???
17:07:39 10433 extract item: example.com@???
17:07:39 10433 todestination1 router generated example.com@???
17:07:39 10433   errors_to=NULL transport=NULL
17:07:39 10433   uid=unset gid=unset home=NULL
17:07:39 10433 routed by todestination1 router (unseen)
17:07:39 10433   envelope to: example.com@???
17:07:39 10433   transport: <none>
17:07:39 10433 "unseen" set: replicated example.com@???
17:07:39 10433 locking /var/spool/exim/db/retry.lockfile
17:07:39 10433 locked /var/spool/exim/db/retry.lockfile
17:07:39 10433 EXIM_DBOPEN(/var/spool/exim/db/retry)
17:07:39 10433 returned from EXIM_DBOPEN
17:07:39 10433 opened hints database /var/spool/exim/db/retry: flags=O_RDONLY
17:07:39 10433 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10433 Considering: example.com@???
17:07:39 10433 unique = \0\example.com@???
17:07:39 10433 dbfn_read: key=R:example.com
17:07:39 10433 dbfn_read: key=R:example.com@???
17:07:39 10433 dbfn_read: key=R:example.com@???:<example.com@???>
17:07:39 10433 no domain retry record
17:07:39 10433 no address retry record
17:07:39 10433 example.com@???: queued for routing
17:07:39 10433 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10433 Considering: example.com@???
17:07:39 10433 unique = \0\example.com@???
17:07:39 10433 dbfn_read: key=R:example.com
17:07:39 10433 dbfn_read: key=R:example.com@???
17:07:39 10433 dbfn_read: key=R:example.com@???:<example.com@???>
17:07:39 10433 no domain retry record
17:07:39 10433 no address retry record
17:07:39 10433 example.com@???: queued for routing
17:07:39 10433 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10433 routing example.com@???
17:07:39 10433 --------> router11 router <--------
17:07:39 10433 local_part=example.com domain=example.com
17:07:39 10433 calling router11 router
17:07:39 10433 router11 router called for example.com@???
17:07:39 10433   domain = example.com
17:07:39 10433 original list of hosts = "10.30.32.41" options = 
17:07:39 10433 expanded list of hosts = "10.30.32.41" options = 
17:07:39 10433 set transport mytransport11
17:07:39 10433 finding IP address for 10.30.32.41
17:07:39 10433 calling host_find_byname
17:07:39 10433 gethostbyname2(af=inet6) returned 1 (HOST_NOT_FOUND)
17:07:39 10433 Actual local interface address is 127.0.0.1 (lo)
17:07:39 10433 Actual local interface address is 10.21.20.250 (eth0)
17:07:39 10433 Actual local interface address is fe80::250:56ff:fe8d:6b2e (eth0)
17:07:39 10433 Actual local interface address is ::1 (lo)
17:07:39 10433 fully qualified name = 10.30.32.41
17:07:39 10433 gethostbyname2 looked up these IP addresses:
17:07:39 10433   name=10.30.32.41 address=10.30.32.41
17:07:39 10433 queued for mytransport11 transport: local_part = example.com
17:07:39 10433 domain = example.com
17:07:39 10433   errors_to=NULL
17:07:39 10433   domain_data=NULL localpart_data=NULL
17:07:39 10433 routed by router11 router
17:07:39 10433   envelope to: example.com@???
17:07:39 10433   transport: mytransport11
17:07:39 10433   host 10.30.32.41 [10.30.32.41] rgroup=-2
17:07:39 10433 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10433 routing example.com@???
17:07:39 10433 --------> savetodisk router <--------
17:07:39 10433 local_part=example.com domain=example.com
17:07:39 10433 calling savetodisk router
17:07:39 10433 savetodisk router called for example.com@???
17:07:39 10433   domain = example.com
17:07:39 10433 set transport buffer_mail
17:07:39 10433 queued for buffer_mail transport: local_part = example.com
17:07:39 10433 domain = example.com
17:07:39 10433   errors_to=NULL
17:07:39 10433   domain_data=NULL localpart_data=NULL
17:07:39 10433 routed by savetodisk router
17:07:39 10433   envelope to: example.com@???
17:07:39 10433   transport: buffer_mail
17:07:39 10433 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:07:39 10433 After routing:
17:07:39 10433   Local deliveries:
17:07:39 10433     example.com@???
17:07:39 10433   Remote deliveries:
17:07:39 10433     example.com@???
17:07:39 10433   Failed addresses:
17:07:39 10433   Deferred addresses:
17:07:39 10433 search_tidyup called
17:07:39 10433 \0\example.com@??? is a duplicate address: discarded
17:07:39 10433 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
17:07:39 10433 --------> example.com@??? <--------
17:07:39 10433 locking /var/spool/exim/db/retry.lockfile
17:07:39 10433 locked /var/spool/exim/db/retry.lockfile
17:07:39 10433 EXIM_DBOPEN(/var/spool/exim/db/retry)
17:07:39 10433 returned from EXIM_DBOPEN
17:07:39 10433 opened hints database /var/spool/exim/db/retry: flags=O_RDONLY
17:07:39 10433 dbfn_read: key=T:example.com@???
17:07:39 10433 no retry record exists
17:07:39 10433 search_tidyup called
17:07:39 10435 changed uid/gid: local delivery to example.com <example.com@???> transport=buffer_mail
17:07:39 10435   uid=93 gid=93 pid=10435
17:07:39 10435   auxiliary group list: <none>
17:07:39 10435   home=NULL current=/
17:07:39 10435 set_process_info: 10435 delivering 1ZS6pv-0002iG-QL to example.com using buffer_mail
17:07:39 10435 appendfile transport entered
17:07:39 10435 expanding: /hwr10pool/data/$local_part/$local_part$local_part_suffix
17:07:39 10435    result: /hwr10pool/data/example.com/example.com
17:07:39 10435 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
17:07:39 10435   directory=/hwr10pool/data/example.com/example.com format=smail
17:07:39 10435   message_prefix=
17:07:39 10435   message_suffix=
17:07:39 10435   maildir_use_size_file=no
17:07:39 10435 delivering to new file in /hwr10pool/data/example.com/example.com
17:07:39 10435 writing to file /hwr10pool/data/example.com/example.com/temp.10435.spool1.example.com
17:07:39 10435 writing data block fd=6 size=565 timeout=0
17:07:39 10435 renaming temporary file
17:07:39 10435 expanding: ${tod_log}${tod_zone}
17:07:39 10435    result: 2015-08-19 17:07:39+0000
17:07:39 10435 expanding:  
17:07:39 10435    result:  
17:07:39 10435 expanding: _
17:07:39 10435    result: _
17:07:39 10435 expanding: ${tr{${tod_log}${tod_zone}}{ }{_}}_${inode}.msg
17:07:39 10435    result: 2015-08-19_17:07:39+0000_394602.msg
17:07:39 10435 appendfile yields 0 with errno=0 more_errno=0
17:07:39 10435 search_tidyup called
17:07:39 10433 journalling example.com@???/buffer_mail
17:07:39 10433 buffer_mail transport returned OK for example.com@???
17:07:39 10433 post-process example.com@??? (0)
17:07:39 10433 example.com@??? delivered
17:07:39 10433 example.com@???: children all complete
17:07:39 10433 LOG: MAIN
17:07:39 10433   => example.com <example.com@???> F=<example.com@???> P=<example.com@???> R=savetodisk T=buffer_mail S=565 QT=0s DT=0s
17:07:39 10433 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
17:07:39 10433 changed uid/gid: post-delivery tidying
17:07:39 10433   uid=93 gid=93 pid=10433
17:07:39 10433   auxiliary group list: <none>
17:07:39 10433 set_process_info: 10433 tidying up after delivering 1ZS6pv-0002iG-QL
17:07:39 10433 Processing retry items
17:07:39 10433 Succeeded addresses:
17:07:39 10433 example.com@???: no retry items
17:07:39 10433 example.com@???: no retry items
17:07:39 10433 example.com@???: no retry items
17:07:39 10433 example.com@???: no retry items
17:07:39 10433 Failed addresses:
17:07:39 10433 Deferred addresses:
17:07:39 10433 end of retry processing
17:07:39 10433 LOG: MAIN
17:07:39 10433   Completed QT=0s
17:07:39 10433 end delivery of 1ZS6pv-0002iG-QL
17:07:39 10433 search_tidyup called
17:07:39 10433 search_tidyup called
17:07:39 10433 >>>>>>>>>>>>>>>> Exim pid=10433 terminating with rc=0 >>>>>>>>>>>>>>>>