Re: [exim] SOLVED: recepient verification callout with defer…

Startseite
Nachricht löschen
Nachricht beantworten
Autor: Heiko Schlittermann
Datum:  
To: exim-users
Betreff: Re: [exim] SOLVED: recepient verification callout with defer_ok fails on graylisted server with error code 450
Hi Volker,

Dr. Volker Jaenisch via Exim-users <exim-users@???> (Fr 07 Jul 2017 08:54:02 CEST):
> There were two problems. First the defer_ok Flag should be used twice as
> Lena mentioned.
>
> verify = recipient/defer_ok/callout=10s,defer_ok,use_sender
>
> Second the callout timeout was 2m and therefore to long for the
> SMTP-Clients which run into SMTP/TCP-timeout
> before completing the Callout.


SMTP client? If you're talking about a MUA, you are right. They often
cancel the connection quite soon. If your client is another MTA, it
should have a bit more patiency.

> Additionally the target system has (maybe intentional) one dysfunctional
> (time at each connect) mailserver prioritized above the others. Maybe
> this is to scare away SPAMMERS. Nevertheless it contributes to the
> problem negatively.


I think it is called MX sandwiching, and some people like it. I'm not
sure if it interoperates well with all mail systems. I got reports about
problems receiving messages from G*. Maybe the admins at HTW put there
some whitelists.

But… I still believe, the defer_ok having twice isn't part of the
solution (one defer_ok is for the callout, the 2nd is for "normal"
recipient verification.)

I've used a small test scenario:

|    keep_environment =
|    tls_advertise_hosts =
|    spool_directory = /tmp/exim

|
|    acl_smtp_rcpt = acl_check_rcpt

|
|    begin acl

|
|
|    acl_check_rcpt:
|            
|            require message = REJECTED: $acl_verify_message
|                    verify = recipient/callout=10s,use_sender,defer_ok
|                    logwrite = verification succeeded for $sender_address $local_part@$domain

|
|            accept

|
|    begin routers

|
|            dns:
|            driver = dnslookup
|            transport = smtp

|
|
|    begin transports

|
|            smtp:
|            driver = smtp


And for testing I used:

    swaks -f '<hs@???>' -t '<***@htw-dresden.de>' \
        --pipe 'exim -C /tmp/exim.test -bhc 8.8.4.4'


In line 204 of the following log you can see, that the message gets
accepted, even all our callout attempts got a 4xx or even a connection
timeout (line 51)

Here the log:
     1  === Trying pipe to /usr/local/exim/bin/exim -C /tmp/exim.test -bhc 8.8.8.8...
     2  === Connected to /usr/local/exim/bin/exim -C /tmp/exim.test -bhc 8.8.8.8.
     3  >>> host in hosts_connection_nolog? no (option unset)
     4  >>> host in host_lookup? no (option unset)
     5  >>> host in host_reject_connection? no (option unset)
     6  >>> host in sender_unqualified_hosts? no (option unset)
     7  >>> host in recipient_unqualified_hosts? no (option unset)
     8  >>> host in helo_verify_hosts? no (option unset)
     9  >>> host in helo_try_verify_hosts? no (option unset)
    10  >>> host in helo_accept_junk_hosts? no (option unset)
    11  <-  
    12  <-  **** SMTP testing session as if from host 8.8.8.8
    13  <-  **** but without any ident (RFC 1413) callback.
    14  <-  **** This is not for real!
    15  <-  
    16  <-  220 pop.net.schlittermann.de ESMTP Exim 4.89_8-aa105ab-XX Fri, 07 Jul 2017 12:42:22 +0200
    17   -> EHLO pop.net.schlittermann.de
    18  >>> pop.net.schlittermann.de in helo_lookup_domains? yes (matched "@")
    19  >>> looking up host name for 8.8.8.8
    20  >>> IP address lookup yielded "google-public-dns-a.google.com"
    21  >>> checking addresses for google-public-dns-a.google.com
    22  >>>   2001:4860:4860::8888
    23  >>>   8.8.8.8 OK
    24  >>> host in dsn_advertise_hosts? no (option unset)
    25  >>> host in pipelining_advertise_hosts? yes (matched "*")
    26  >>> host in chunking_advertise_hosts? yes (matched "*")
    27  >>> host in tls_advertise_hosts? no (end of list)
    28  <-  250-pop.net.schlittermann.de Hello google-public-dns-a.google.com [8.8.8.8]
    29  <-  250-SIZE 52428800
    30  <-  250-8BITMIME
    31  <-  250-PIPELINING
    32  <-  250-CHUNKING
    33  <-  250 HELP
    34   -> MAIL FROM:<hs@???>
    35  <-  250 OK
    36   -> RCPT TO:<***@htw-dresden.de>
    37  >>> using ACL "acl_check_rcpt"
    38  >>> processing "require"
    39  >>>   message: REJECTED: $acl_verify_message
    40  >>> check verify = recipient/callout=10s,use_sender,defer_ok
    41  >>> >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
    42  >>> routing ***@htw-dresden.de
    43  >>> calling dns router
    44  >>> routed by dns router
    45  >>> Attempting full verification using callout
    46  >>> callout cache: no domain record found for htw-dresden.de
    47  >>> callout cache: no address record found for ***@htw-dresden.de/<hs@???>
    48  >>> 141.56.16.45 in hosts_require_dane? no (option unset)
    49  >>> interface=NULL port=25
    50  >>> Connecting to rlux45.rz.htw-dresden.de [141.56.16.45]:25 ... failed: Connection timed out (timeout=10s)
    51  >>> connect: Connection timed out
    52  >>> SMTP timeout
    53  >>> 141.56.16.134 in hosts_require_dane? no (option unset)
    54  >>> interface=NULL port=25
    55  >>> Connecting to rmx4.rz.htw-dresden.de [141.56.16.134]:25 ... connected
    56  >>>   SMTP<< 220 rmx4.rz.htw-dresden.de ESMTP Postfix (Debian/GNU)
    57  >>> 141.56.16.134 in hosts_avoid_esmtp? no (option unset)
    58  >>>   SMTP>> EHLO pop.net.schlittermann.de
    59  >>> cmd buf flush 31 bytes
    60  >>>   SMTP<< 250-rmx4.rz.htw-dresden.de
    61  >>>          250-PIPELINING
    62  >>>          250-SIZE 30720000
    63  >>>          250-VRFY
    64  >>>          250-ETRN
    65  >>>          250-STARTTLS
    66  >>>          250-ENHANCEDSTATUSCODES
    67  >>>          250-8BITMIME
    68  >>>          250 DSN
    69  >>> 141.56.16.134 in hosts_avoid_tls? no (option unset)
    70  >>> 141.56.16.134 in hosts_verify_avoid_tls? no (option unset)
    71  >>>   SMTP>> STARTTLS
    72  >>> cmd buf flush 10 bytes
    73  >>>   SMTP<< 220 2.0.0 Ready to start TLS
    74  >>> 141.56.16.134 in hosts_require_ocsp? no (option unset)
    75  >>> 141.56.16.134 in hosts_request_ocsp? yes (matched "*")
    76  >>> 141.56.16.134 in tls_verify_hosts? no (option unset)
    77  >>> 141.56.16.134 in tls_try_verify_hosts? yes (matched "*")
    78  >>> 141.56.16.134 in tls_verify_cert_hostnames? yes (matched "*")
    79  LOG: [141.56.16.134] SSL verify error: depth=0 error=self signed certificate cert=/CN=rmx4.rz.htw-dresden.de
    80  >>>   SMTP>> EHLO pop.net.schlittermann.de
    81  >>> cmd buf flush 31 bytes
    82  >>>   SMTP<< 250-rmx4.rz.htw-dresden.de
    83  >>>          250-PIPELINING
    84  >>>          250-SIZE 30720000
    85  >>>          250-VRFY
    86  >>>          250-ETRN
    87  >>>          250-ENHANCEDSTATUSCODES
    88  >>>          250-8BITMIME
    89  >>>          250 DSN
    90  >>> 141.56.16.134 in hosts_avoid_pipelining? no (option unset)
    91  >>> 141.56.16.134 in hosts_require_auth? no (option unset)
    92  >>>   SMTP>> MAIL FROM:<hs@???> SIZE=1023
    93  >>>   SMTP>> RCPT TO:<***@htw-dresden.de>
    94  >>> cmd buf flush 85 bytes
    95  >>>   SMTP<< 250 2.1.0 Ok
    96  >>>   SMTP<< 450 4.2.0 <***@htw-dresden.de>: Recipient address rejected: Greylisted, see http://postgrey.schweikert.ch/help/htw-dresden.de.html
    97  >>>   SMTP>> QUIT
    98  >>> cmd buf flush 6 bytes
    99  >>>   SMTP<< 221 2.0.0 Bye
   100  >>>   SMTP(close)>>
   101  >>> 141.56.16.135 in hosts_require_dane? no (option unset)
   102  >>> interface=NULL port=25
   103  >>> Connecting to rmx5.rz.htw-dresden.de [141.56.16.135]:25 ... connected
   104  >>>   SMTP<< 220 rmx5.rz.htw-dresden.de ESMTP Postfix (Debian/GNU)
   105  >>> 141.56.16.135 in hosts_avoid_esmtp? no (option unset)
   106  >>>   SMTP>> EHLO pop.net.schlittermann.de
   107  >>> cmd buf flush 31 bytes
   108  >>>   SMTP<< 250-rmx5.rz.htw-dresden.de
   109  >>>          250-PIPELINING
   110  >>>          250-SIZE 30720000
   111  >>>          250-VRFY
   112  >>>          250-ETRN
   113  >>>          250-STARTTLS
   114  >>>          250-ENHANCEDSTATUSCODES
   115  >>>          250-8BITMIME
   116  >>>          250 DSN
   117  >>> 141.56.16.135 in hosts_avoid_tls? no (option unset)
   118  >>> 141.56.16.135 in hosts_verify_avoid_tls? no (option unset)
   119  >>>   SMTP>> STARTTLS
   120  >>> cmd buf flush 10 bytes
   121  >>>   SMTP<< 220 2.0.0 Ready to start TLS
   122  >>> 141.56.16.135 in hosts_require_ocsp? no (option unset)
   123  >>> 141.56.16.135 in hosts_request_ocsp? yes (matched "*")
   124  >>> 141.56.16.135 in tls_verify_hosts? no (option unset)
   125  >>> 141.56.16.135 in tls_try_verify_hosts? yes (matched "*")
   126  >>> 141.56.16.135 in tls_verify_cert_hostnames? yes (matched "*")
   127  LOG: [141.56.16.135] SSL verify error: depth=0 error=self signed certificate cert=/CN=rts2.rz.htw-dresden.de
   128  LOG: [141.56.16.135] SSL verify error: certificate name mismatch: DN="/CN=rts2.rz.htw-dresden.de" H="rmx5.rz.htw-dresden.de"
   129  >>>   SMTP>> EHLO pop.net.schlittermann.de
   130  >>> cmd buf flush 31 bytes
   131  >>>   SMTP<< 250-rmx5.rz.htw-dresden.de
   132  >>>          250-PIPELINING
   133  >>>          250-SIZE 30720000
   134  >>>          250-VRFY
   135  >>>          250-ETRN
   136  >>>          250-ENHANCEDSTATUSCODES
   137  >>>          250-8BITMIME
   138  >>>          250 DSN
   139  >>> 141.56.16.135 in hosts_avoid_pipelining? no (option unset)
   140  >>> 141.56.16.135 in hosts_require_auth? no (option unset)
   141  >>>   SMTP>> MAIL FROM:<hs@???> SIZE=1023
   142  >>>   SMTP>> RCPT TO:<***@htw-dresden.de>
   143  >>> cmd buf flush 85 bytes
   144  >>>   SMTP<< 250 2.1.0 Ok
   145  >>>   SMTP<< 450 4.2.0 <***@htw-dresden.de>: Recipient address rejected: Greylisted, see http://postgrey.schweikert.ch/help/htw-dresden.de.html
   146  >>>   SMTP>> QUIT
   147  >>> cmd buf flush 6 bytes
   148  >>>   SMTP<< 221 2.0.0 Bye
   149  >>>   SMTP(close)>>
   150  >>> 141.56.16.136 in hosts_require_dane? no (option unset)
   151  >>> interface=NULL port=25
   152  >>> Connecting to rmx6.rz.htw-dresden.de [141.56.16.136]:25 ... connected
   153  >>>   SMTP<< 220 rmx6.rz.htw-dresden.de ESMTP Postfix (Debian/GNU)
   154  >>> 141.56.16.136 in hosts_avoid_esmtp? no (option unset)
   155  >>>   SMTP>> EHLO pop.net.schlittermann.de
   156  >>> cmd buf flush 31 bytes
   157  >>>   SMTP<< 250-rmx6.rz.htw-dresden.de
   158  >>>          250-PIPELINING
   159  >>>          250-SIZE 30720000
   160  >>>          250-VRFY
   161  >>>          250-ETRN
   162  >>>          250-STARTTLS
   163  >>>          250-ENHANCEDSTATUSCODES
   164  >>>          250-8BITMIME
   165  >>>          250 DSN
   166  >>> 141.56.16.136 in hosts_avoid_tls? no (option unset)
   167  >>> 141.56.16.136 in hosts_verify_avoid_tls? no (option unset)
   168  >>>   SMTP>> STARTTLS
   169  >>> cmd buf flush 10 bytes
   170  >>>   SMTP<< 220 2.0.0 Ready to start TLS
   171  >>> 141.56.16.136 in hosts_require_ocsp? no (option unset)
   172  >>> 141.56.16.136 in hosts_request_ocsp? yes (matched "*")
   173  >>> 141.56.16.136 in tls_verify_hosts? no (option unset)
   174  >>> 141.56.16.136 in tls_try_verify_hosts? yes (matched "*")
   175  >>> 141.56.16.136 in tls_verify_cert_hostnames? yes (matched "*")
   176  LOG: [141.56.16.136] SSL verify error: depth=0 error=self signed certificate cert=/CN=rmx6.rz.htw-dresden.de
   177  >>>   SMTP>> EHLO pop.net.schlittermann.de
   178  >>> cmd buf flush 31 bytes
   179  >>>   SMTP<< 250-rmx6.rz.htw-dresden.de
   180  >>>          250-PIPELINING
   181  >>>          250-SIZE 30720000
   182  >>>          250-VRFY
   183  >>>          250-ETRN
   184  >>>          250-ENHANCEDSTATUSCODES
   185  >>>          250-8BITMIME
   186  >>>          250 DSN
   187  >>> 141.56.16.136 in hosts_avoid_pipelining? no (option unset)
   188  >>> 141.56.16.136 in hosts_require_auth? no (option unset)
   189  >>>   SMTP>> MAIL FROM:<hs@???> SIZE=1023
   190  >>>   SMTP>> RCPT TO:<***@htw-dresden.de>
   191  >>> cmd buf flush 85 bytes
   192  >>>   SMTP<< 250 2.1.0 Ok
   193  >>>   SMTP<< 450 4.2.0 <***@htw-dresden.de>: Recipient address rejected: Greylisted, see http://postgrey.schweikert.ch/help/htw-dresden.de.html
   194  >>>   SMTP>> QUIT
   195  >>> cmd buf flush 6 bytes
   196  >>>   SMTP<< 221 2.0.0 Bye
   197  >>>   SMTP(close)>>
   198  >>> wrote callout cache domain record for htw-dresden.de:
   199  >>>   result=1 postmaster=0 random=0
   200  >>> ----------- end verify ------------
   201  >>> verify defer overridden by callout_defer_ok
   202  >>> check logwrite = verification succeeded for $sender_address $local_part@$domain
   203  >>>                = verification succeeded for hs@??? ***@htw-dresden.de
   204  LOG: verification succeeded for hs@??? ***@htw-dresden.de
   205  >>> require: condition test succeeded in ACL "acl_check_rcpt"
   206  >>> processing "accept"
   207  >>> accept: condition test succeeded in ACL "acl_check_rcpt"
   208  >>> end of ACL "acl_check_rcpt": ACCEPT
   209  <-  250 Accepted
   210   -> DATA
   211  <-  354 Enter message, ending with "." on a line by itself
   212   -> Date: Fri, 07 Jul 2017 12:42:22 +0200
   213   -> To: ***@htw-dresden.de
   214   -> From: hs@???
   215   -> Subject: test Fri, 07 Jul 2017 12:42:22 +0200
   216   -> X-Mailer: swaks v20120320.0 jetmore.org/john/code/swaks/
   217   -> 
   218   -> This is a test mailing
   219   -> 
   220   -> .
   221  >>> host in ignore_fromline_hosts? no (option unset)
   222  LOG: 1dTQiX-0006zS-D3 <= hs@??? H=google-public-dns-a.google.com (pop.net.schlittermann.de) [8.8.8.8] P=esmtp S=509
   223  <-  250 OK id=1dTQiX-0006zS-D3
   224   -> QUIT
   225  <-  
   226  <-  **** SMTP testing: that is not a real message id!
   227  <-  
   228  <-  221 pop.net.schlittermann.de closing connection
   229  === Connection closed with child process.