On 2014-01-19 Juliusz Chroboczek <j...@pps.univ-paris-diderot.fr> wrote: >> You seem to be quoting two different outputs, one with and and one >> without debugging info.
> I've just sent the relevant excerpts. Hello, The log for the successful one does not included any lookups, while the failing one has a a tiny bit of lookups. So either exim guessed the correct password or you quoted different things. >> Please show the debugging output with and without >> AUTH_CLIENT_ALLOW_NOTLS_PASSWORDS (take care to remove >> username/password from the output) > If there's anything particular in the debug output, I'll be glad to > send you the info. On the other hand, I'd rather not spend time > anonymising the full output. I really do not get the whole "need to anonymising the full output" thing. It is not like your SMTP smarthost or e-mail address are secret. And obfuscated output makes debugging hard to impossible. Take the debugging output, find your smtp-password and smtp-login in it and do a search and replace, done. See attached for an example. https://github.com/Exim/exim/wiki/DontObfuscate >> Also is there a reason why you say x.x.x.x instead of showing the IP >> address? Did you customize the authenticator? > No, I didn't customise anything. > I'm not the only person having this issue -- see > https://www.google.fr/search?q="plain+authenticator+yielded+13" These are usually caused by not using the canonical hostname in passwd.client and not solved the disabling the TLS check. cu Andreas -- `What a good friend you are to him, Dr. Maturin. His other friends are so grateful to you.' `I sew his ears on from time to time, sure'
17:17:40 30529 Exim version 4.82 uid=0 gid=0 pid=30529 D=fffdffff Berkeley DB: Berkeley DB 5.1.29: (October 25, 2011) Support for: crypteq iconv() IPv6 GnuTLS move_frozen_messages DKIM Lookups (built-in): lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmjz dbmnz dnsdb dsearch nis nis0 passwd Authenticators: cram_md5 plaintext Routers: accept dnslookup ipliteral manualroute queryprogram redirect Transports: appendfile/maildir/mailstore autoreply lmtp pipe smtp Fixed never_users: 0 Size of off_t: 8 Compiler: GCC [4.8.2] Library version: GnuTLS: Compile: 2.12.23 Runtime: 2.12.23 Library version: PCRE: Compile: 8.31 Runtime: 8.31 2012-07-06 17:17:40 30529 Total 13 lookups WHITELIST_D_MACROS: "OUTGOING" TRUSTED_CONFIG_LIST: "/etc/exim4/trusted_configs" 17:17:40 30529 changed uid/gid: forcing real = effective 17:17:40 30529 uid=0 gid=0 pid=30529 17:17:40 30529 auxiliary group list: <none> 17:17:40 30529 seeking password data for user "uucp": cache not available 17:17:40 30529 getpwnam() succeeded uid=10 gid=10 17:17:40 30531 changed uid/gid: calling tls_validate_require_cipher 17:17:40 30531 uid=102 gid=103 pid=30531 17:17:40 30531 auxiliary group list: <none> 17:17:40 30529 tls_validate_require_cipher child 30531 ended: status=0x0 17:17:40 30529 configuration file is /var/lib/exim4/config.autogenerated 17:17:40 30529 log selectors = 00000ffc 00632001 17:17:40 30529 cwd=/ 5 args: exim4 -d+all -f ametz...@gmx.net ametz...@bebt.de 17:17:40 30529 trusted user 17:17:40 30529 admin user 17:17:40 30529 changed uid/gid: privilege not needed 17:17:40 30529 uid=102 gid=103 pid=30529 17:17:40 30529 auxiliary group list: 103 17:17:40 30529 seeking password data for user "mail": cache not available 17:17:40 30529 getpwnam() succeeded uid=8 gid=8 17:17:40 30529 originator: uid=0 gid=0 login=root name= 17:17:40 30529 sender address = ametz...@gmx.net 17:17:40 30529 set_process_info: 30529 accepting a local non-SMTP message from <ametz...@gmx.net> 17:17:40 30529 Sender: ametz...@gmx.net 17:17:40 30529 Recipients: 17:17:40 30529 ametz...@bebt.de 17:17:40 30529 search_tidyup called 17:17:40 30529 >>Headers received: 17:17:40 30529 17:17:40 30529 address match test: subject=ametz...@gmx.net pattern=*@+local_domains 17:17:40 30529 gmx.net in "@:localhost:argenau"? no (end of list) 17:17:40 30529 gmx.net in "+local_domains"? no (end of list) 17:17:40 30529 ametz...@gmx.net in "*@+local_domains"? no (end of list) 17:17:40 30529 address match test: subject=ametz...@gmx.net pattern=*@argenau 17:17:40 30529 gmx.net in "argenau"? no (end of list) 17:17:40 30529 ametz...@gmx.net in "*@argenau"? no (end of list) 17:17:40 30529 rewritten sender = ametz...@gmx.net 17:17:40 30529 rewrite_one_header: type=F: 17:17:40 30529 From: ametz...@gmx.net 17:17:40 30529 address match test: subject=ametz...@gmx.net pattern=*@+local_domains 17:17:40 30529 gmx.net in "@:localhost:argenau"? no (end of list) 17:17:40 30529 gmx.net in "+local_domains"? no (end of list) 17:17:40 30529 ametz...@gmx.net in "*@+local_domains"? no (end of list) 17:17:40 30529 address match test: subject=ametz...@gmx.net pattern=*@argenau 17:17:40 30529 gmx.net in "argenau"? no (end of list) 17:17:40 30529 ametz...@gmx.net in "*@argenau"? no (end of list) 17:17:40 30529 search_tidyup called 17:17:40 30529 >>Headers after rewriting and local additions: 17:17:40 30529 I Message-Id: <E1W4w0C-0007wP-Kq@argenau> 17:17:40 30529 F From: ametz...@gmx.net 17:17:40 30529 Date: Sun, 19 Jan 2014 17:17:40 +0000 17:17:40 30529 17:17:40 30529 Data file written for message 1W4w0C-0007wP-Kq 17:17:40 30529 expanding: ${tod_full} 17:17:40 30529 result: Sun, 19 Jan 2014 17:17:40 +0000 17:17:40 30529 condition: def:sender_rcvhost 17:17:40 30529 result: false 17:17:40 30529 expanding: from $sender_rcvhost 17:17:40 30529 17:17:40 30529 result: from 17:17:40 30529 17:17:40 30529 skipping: result is not used 17:17:40 30529 condition: def:sender_ident 17:17:40 30529 result: true 17:17:40 30529 expanding: $sender_ident 17:17:40 30529 result: root 17:17:40 30529 expanding: from ${quote_local_part:$sender_ident} 17:17:40 30529 result: from root 17:17:40 30529 condition: def:sender_helo_name 17:17:40 30529 result: false 17:17:40 30529 expanding: (helo=$sender_helo_name) 17:17:40 30529 17:17:40 30529 result: (helo=) 17:17:40 30529 17:17:40 30529 skipping: result is not used 17:17:40 30529 expanding: ${if def:sender_ident {from ${quote_local_part:$sender_ident} }}${if def:sender_helo_name {(helo=$sender_helo_name) 17:17:40 30529 }} 17:17:40 30529 result: from root 17:17:40 30529 condition: def:received_protocol 17:17:40 30529 result: true 17:17:40 30529 expanding: with $received_protocol 17:17:40 30529 result: with local 17:17:40 30529 condition: def:tls_cipher 17:17:40 30529 result: false 17:17:40 30529 expanding: ($tls_cipher) 17:17:40 30529 17:17:40 30529 result: () 17:17:40 30529 17:17:40 30529 skipping: result is not used 17:17:40 30529 condition: def:sender_address 17:17:40 30529 result: true 17:17:40 30529 expanding: (envelope-from <$sender_address>) 17:17:40 30529 17:17:40 30529 result: (envelope-from <ametz...@gmx.net>) 17:17:40 30529 17:17:40 30529 condition: def:received_for 17:17:40 30529 result: true 17:17:40 30529 expanding: 17:17:40 30529 for $received_for 17:17:40 30529 result: 17:17:40 30529 for ametz...@bebt.de 17:17:40 30529 expanding: Received: ${if def:sender_rcvhost {from $sender_rcvhost 17:17:40 30529 }{${if def:sender_ident {from ${quote_local_part:$sender_ident} }}${if def:sender_helo_name {(helo=$sender_helo_name) 17:17:40 30529 }}}}by $primary_hostname ${if def:received_protocol {with $received_protocol}} ${if def:tls_cipher {($tls_cipher) 17:17:40 30529 }}(Exim $version_number) 17:17:40 30529 ${if def:sender_address {(envelope-from <$sender_address>) 17:17:40 30529 }}id $message_exim_id${if def:received_for { 17:17:40 30529 for $received_for}} 17:17:40 30529 result: Received: from root by argenau with local (Exim 4.82) 17:17:40 30529 (envelope-from <ametz...@gmx.net>) 17:17:40 30529 id 1W4w0C-0007wP-Kq 17:17:40 30529 for ametz...@bebt.de 17:17:40 30529 >>Generated Received: header line 17:17:40 30529 P Received: from root by argenau with local (Exim 4.82) 17:17:40 30529 (envelope-from <ametz...@gmx.net>) 17:17:40 30529 id 1W4w0C-0007wP-Kq 17:17:40 30529 for ametz...@bebt.de; Sun, 19 Jan 2014 17:17:40 +0000 17:17:40 30529 calling local_scan(); timeout=300 17:17:40 30529 local_scan() returned 0 NULL 17:17:40 30529 expanding: ${tod_full} 17:17:40 30529 result: Sun, 19 Jan 2014 17:17:40 +0000 17:17:40 30529 Writing spool header file 17:17:40 30529 Size of headers = 267 17:17:40 30529 LOG: MAIN 17:17:40 30529 <= ametz...@gmx.net U=root P=local S=273 17:17:40 30529 search_tidyup called 17:17:40 30529 search_tidyup called 17:17:40 30529 >>>>>>>>>>>>>>>> Exim pid=30529 terminating with rc=0 >>>>>>>>>>>>>>>> 17:17:40 30532 exec /usr/sbin/exim4 -d=0xfffdffff -Mc 1W4w0C-0007wP-Kq 17:17:40 30532 Exim version 4.82 uid=102 gid=103 pid=30532 D=fffdffff Berkeley DB: Berkeley DB 5.1.29: (October 25, 2011) Support for: crypteq iconv() IPv6 GnuTLS move_frozen_messages DKIM Lookups (built-in): lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmjz dbmnz dnsdb dsearch nis nis0 passwd Authenticators: cram_md5 plaintext Routers: accept dnslookup ipliteral manualroute queryprogram redirect Transports: appendfile/maildir/mailstore autoreply lmtp pipe smtp Fixed never_users: 0 Size of off_t: 8 Compiler: GCC [4.8.2] Library version: GnuTLS: Compile: 2.12.23 Runtime: 2.12.23 Library version: PCRE: Compile: 8.31 Runtime: 8.31 2012-07-06 17:17:40 30532 Total 13 lookups WHITELIST_D_MACROS: "OUTGOING" TRUSTED_CONFIG_LIST: "/etc/exim4/trusted_configs" 17:17:40 30532 changed uid/gid: forcing real = effective 17:17:40 30532 uid=0 gid=103 pid=30532 17:17:40 30532 auxiliary group list: <none> 17:17:40 30532 seeking password data for user "uucp": cache not available 17:17:40 30532 getpwnam() succeeded uid=10 gid=10 17:17:40 30533 changed uid/gid: calling tls_validate_require_cipher 17:17:40 30533 uid=102 gid=103 pid=30533 17:17:40 30533 auxiliary group list: <none> 17:17:40 30532 tls_validate_require_cipher child 30533 ended: status=0x0 17:17:40 30532 configuration file is /var/lib/exim4/config.autogenerated 17:17:40 30532 log selectors = 00000ffc 00632001 17:17:40 30532 cwd=/var/spool/exim4 4 args: /usr/sbin/exim4 -d=0xfffdffff -Mc 1W4w0C-0007wP-Kq 17:17:40 30532 trusted user 17:17:40 30532 admin user 17:17:40 30532 seeking password data for user "mail": cache not available 17:17:40 30532 getpwnam() succeeded uid=8 gid=8 17:17:40 30532 set_process_info: 30532 delivering specified messages 17:17:40 30532 set_process_info: 30532 delivering 1W4w0C-0007wP-Kq 17:17:40 30532 reading spool file 1W4w0C-0007wP-Kq-H 17:17:40 30532 user=root uid=0 gid=0 sender=ametz...@gmx.net 17:17:40 30532 sender_local=0 ident=root 17:17:40 30532 Non-recipients: 17:17:40 30532 Empty Tree 17:17:40 30532 ---- End of tree ---- 17:17:40 30532 recipients_count=1 17:17:40 30532 body_linecount=1 message_linecount=7 17:17:40 30532 Delivery address list: 17:17:40 30532 ametz...@bebt.de 17:17:40 30532 locking /var/spool/exim4/db/retry.lockfile 17:17:40 30532 locked /var/spool/exim4/db/retry.lockfile 17:17:40 30532 EXIM_DBOPEN(/var/spool/exim4/db/retry) 17:17:40 30532 returned from EXIM_DBOPEN 17:17:40 30532 no retry data available 17:17:40 30532 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> 17:17:40 30532 Considering: ametz...@bebt.de 17:17:40 30532 unique = ametz...@bebt.de 17:17:40 30532 no domain retry record 17:17:40 30532 no address retry record 17:17:40 30532 ametz...@bebt.de: queued for routing 17:17:40 30532 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> 17:17:40 30532 routing ametz...@bebt.de 17:17:40 30532 --------> hubbed_hosts router <-------- 17:17:40 30532 local_part=ametzler domain=bebt.de 17:17:40 30532 checking domains 17:17:40 30532 expanding: /etc/exim4/hubbed_hosts 17:17:40 30532 result: /etc/exim4/hubbed_hosts 17:17:40 30532 condition: exists{/etc/exim4/hubbed_hosts} 17:17:40 30532 result: false 17:17:40 30532 expanding: partial-lsearch;/etc/exim4/hubbed_hosts 17:17:40 30532 result: partial-lsearch;/etc/exim4/hubbed_hosts 17:17:40 30532 skipping: result is not used 17:17:40 30532 failed to expand: ${if exists{/etc/exim4/hubbed_hosts}{partial-lsearch;/etc/exim4/hubbed_hosts}fail} 17:17:40 30532 error message: "if" failed and "fail" requested 17:17:40 30532 failure was forced 17:17:40 30532 expansion of "${if exists{/etc/exim4/hubbed_hosts}{partial-lsearch;/etc/exim4/hubbed_hosts}fail}" forced failure: assume not in this list 17:17:40 30532 hubbed_hosts router skipped: domains mismatch 17:17:40 30532 --------> smarthost router <-------- 17:17:40 30532 local_part=ametzler domain=bebt.de 17:17:40 30532 checking domains 17:17:40 30532 bebt.de in "@:localhost:argenau"? no (end of list) 17:17:40 30532 bebt.de in "! +local_domains"? yes (end of list) 17:17:40 30532 expanding: R: smarthost for $local_part@$domain 17:17:40 30532 result: R: smarthost for ametz...@bebt.de 17:17:40 30532 R: smarthost for ametz...@bebt.de 17:17:40 30532 calling smarthost router 17:17:40 30532 smarthost router called for ametz...@bebt.de 17:17:40 30532 domain = bebt.de 17:17:40 30532 route_item = * mail.gmx.net byname 17:17:40 30532 bebt.de in "*"? yes (matched "*") 17:17:40 30532 original list of hosts = "mail.gmx.net" options = byname 17:17:40 30532 expanded list of hosts = "mail.gmx.net" options = byname 17:17:40 30532 set transport remote_smtp_smarthost 17:17:40 30532 finding IP address for mail.gmx.net 17:17:40 30532 calling host_find_byname 17:17:40 30532 gethostbyname2(af=inet6) returned 4 (NO_DATA) 17:17:40 30532 Configured local interface: address=127.0.0.1 17:17:40 30532 Configured local interface: address=::1 17:17:40 30532 fully qualified name = mail.gmx.net 17:17:40 30532 gethostbyname2 looked up these IP addresses: 17:17:40 30532 name=mail.gmx.net address=212.227.17.190 17:17:40 30532 name=mail.gmx.net address=212.227.17.168 17:17:40 30532 queued for remote_smtp_smarthost transport: local_part = ametzler 17:17:40 30532 domain = bebt.de 17:17:40 30532 errors_to=NULL 17:17:40 30532 domain_data=NULL localpart_data=NULL 17:17:40 30532 routed by smarthost router 17:17:40 30532 envelope to: ametz...@bebt.de 17:17:40 30532 transport: remote_smtp_smarthost 17:17:40 30532 host mail.gmx.net [212.227.17.190] 17:17:40 30532 host mail.gmx.net [212.227.17.168] 17:17:40 30532 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> 17:17:40 30532 After routing: 17:17:40 30532 Local deliveries: 17:17:40 30532 Remote deliveries: 17:17:40 30532 ametz...@bebt.de 17:17:40 30532 Failed addresses: 17:17:40 30532 Deferred addresses: 17:17:40 30532 search_tidyup called 17:17:40 30532 >>>>>>>>>>>>>>>> Remote deliveries >>>>>>>>>>>>>>>> 17:17:40 30532 --------> ametz...@bebt.de <-------- 17:17:40 30532 search_tidyup called 17:17:40 30532 set_process_info: 30532 delivering 1W4w0C-0007wP-Kq: waiting for a remote delivery subprocess to finish 17:17:40 30532 selecting on subprocess pipes 17:17:40 30534 changed uid/gid: remote delivery to ametz...@bebt.de with transport=remote_smtp_smarthost 17:17:40 30534 uid=102 gid=103 pid=30534 17:17:40 30534 auxiliary group list: <none> 17:17:40 30534 set_process_info: 30534 delivering 1W4w0C-0007wP-Kq using remote_smtp_smarthost 17:17:40 30534 expanding: T: remote_smtp_smarthost for $local_part@$domain 17:17:40 30534 result: T: remote_smtp_smarthost for ametz...@bebt.de 17:17:40 30534 T: remote_smtp_smarthost for ametz...@bebt.de 17:17:40 30534 remote_smtp_smarthost transport entered 17:17:40 30534 ametz...@bebt.de 17:17:40 30534 bebt.de in queue_smtp_domains? no (option unset) 17:17:40 30534 checking status of mail.gmx.net 17:17:40 30534 locking /var/spool/exim4/db/retry.lockfile 17:17:40 30534 locked /var/spool/exim4/db/retry.lockfile 17:17:40 30534 EXIM_DBOPEN(/var/spool/exim4/db/retry) 17:17:40 30534 returned from EXIM_DBOPEN 17:17:40 30534 no retry data available 17:17:40 30534 mail.gmx.net [212.227.17.190] status = usable 17:17:40 30534 212.227.17.190 in serialize_hosts? no (option unset) 17:17:40 30534 delivering 1W4w0C-0007wP-Kq to mail.gmx.net [212.227.17.190] (ametz...@bebt.de) 17:17:40 30534 set_process_info: 30534 delivering 1W4w0C-0007wP-Kq to mail.gmx.net [212.227.17.190] (ametz...@bebt.de) 17:17:40 30534 Connecting to mail.gmx.net [212.227.17.190]:25 ... connected 17:17:40 30534 expanding: $primary_hostname 17:17:40 30534 result: argenau 17:17:40 30534 waiting for data on socket 17:17:40 30534 read response data: size=52 17:17:40 30534 SMTP<< 220 gmx.com (mrgmx003) Nemesis ESMTP Service ready 17:17:40 30534 212.227.17.190 in hosts_avoid_esmtp? no (option unset) 17:17:40 30534 SMTP>> EHLO argenau 17:17:40 30534 waiting for data on socket 17:17:40 30534 read response data: size=98 17:17:40 30534 SMTP<< 250-gmx.com Hello argenau [188.23.64.214] 17:17:40 30534 250-SIZE 69920427 17:17:40 30534 250-AUTH LOGIN PLAIN 17:17:40 30534 250 STARTTLS 17:17:40 30534 212.227.17.190 in hosts_avoid_tls? no (option unset) 17:17:40 30534 SMTP>> STARTTLS 17:17:40 30534 waiting for data on socket 17:17:40 30534 read response data: size=8 17:17:40 30534 SMTP<< 220 OK 17:17:40 30534 initialising GnuTLS as a client on fd 7 17:17:40 30534 GnuTLS global init required. 17:17:40 30534 initialising GnuTLS client session 17:17:40 30534 Expanding various TLS configuration options for session credentials. 17:17:40 30534 TLS: no client certificate specified; okay 17:17:40 30534 TLS: tls_verify_certificates not set or empty, ignoring 17:17:40 30534 GnuTLS using default session cipher/priority "NORMAL" 17:17:40 30534 Setting D-H prime minimum acceptable bits to 1024 17:17:40 30534 TLS: server certificate verification not required 17:17:41 30534 gnutls_handshake was successful 17:17:41 30534 cipher: TLS1.2:RSA_AES_128_CBC_SHA1:128 17:17:41 30534 Have channel bindings cached for possible auth usage. 17:17:41 30534 SMTP>> EHLO argenau 17:17:41 30534 tls_do_write(0xffb1768c, 14) 17:17:41 30534 gnutls_record_send(SSL, 0xffb1768c, 14) 17:17:41 30534 outbytes=14 17:17:41 30534 waiting for data on socket 17:17:41 30534 Calling gnutls_record_recv(0xf7e5e438, 0xffb18a8c, 4096) 17:17:41 30534 read response data: size=84 17:17:41 30534 SMTP<< 250-gmx.com Hello argenau [188.23.64.214] 17:17:41 30534 250-SIZE 69920427 17:17:41 30534 250 AUTH LOGIN PLAIN 17:17:41 30534 212.227.17.190 in hosts_avoid_pipelining? no (option unset) 17:17:41 30534 not using PIPELINING 17:17:41 30534 212.227.17.190 in hosts_require_auth? no (option unset) 17:17:41 30534 expanding: /etc/exim4/passwd.client 17:17:41 30534 result: /etc/exim4/passwd.client 17:17:41 30534 condition: exists{/etc/exim4/passwd.client} 17:17:41 30534 result: true 17:17:41 30534 expanding: $host 17:17:41 30534 result: mail.gmx.net 17:17:41 30534 expanding: /etc/exim4/passwd.client 17:17:41 30534 result: /etc/exim4/passwd.client 17:17:41 30534 search_open: nwildlsearch "/etc/exim4/passwd.client" 17:17:41 30534 search_find: file="/etc/exim4/passwd.client" 17:17:41 30534 key="mail.gmx.net" partial=-1 affix=NULL starflags=0 17:17:41 30534 LRU list: 17:17:41 30534 :/etc/exim4/passwd.client 17:17:41 30534 End 17:17:41 30534 internal_search_find: file="/etc/exim4/passwd.client" 17:17:41 30534 type=nwildlsearch key="mail.gmx.net" 17:17:41 30534 file lookup required for mail.gmx.net 17:17:41 30534 in /etc/exim4/passwd.client 17:17:41 30534 mail.gmx.net in "mail.gmx.net"? yes (matched "mail.gmx.net") 17:17:41 30534 lookup yielded: MYSMTPLOGIN:MYSMTPPASSWORD 17:17:41 30534 expanding: $host_address 17:17:41 30534 result: 212.227.17.190 17:17:41 30534 expanding: ${lookup{$host}nwildlsearch{/etc/exim4/passwd.client}{$host_address}} 17:17:41 30534 result: 212.227.17.190 17:17:41 30534 expanding: 17:17:41 30534 result: 17:17:41 30534 skipping: result is not used 17:17:41 30534 expanding: <; ${if exists{/etc/exim4/passwd.client} {${lookup{$host}nwildlsearch{/etc/exim4/passwd.client}{$host_address}}}{} } 17:17:41 30534 result: <; 212.227.17.190 17:17:41 30534 212.227.17.190 in hosts_try_auth? yes (matched "212.227.17.190") 17:17:41 30534 scanning authentication mechanisms 17:17:41 30534 expanding: $tls_out_cipher 17:17:41 30534 result: TLS1.2:RSA_AES_128_CBC_SHA1:128 17:17:41 30534 expanding: 17:17:41 30534 result: 17:17:41 30534 condition: !eq{$tls_out_cipher}{} 17:17:41 30534 result: true 17:17:41 30534 expanding: 1 17:17:41 30534 result: 1 17:17:41 30534 expanding: : 17:17:41 30534 result: : 17:17:41 30534 expanding: $host 17:17:41 30534 result: mail.gmx.net 17:17:41 30534 expanding: /etc/exim4/passwd.client 17:17:41 30534 result: /etc/exim4/passwd.client 17:17:41 30534 search_open: nwildlsearch "/etc/exim4/passwd.client" 17:17:41 30534 cached open 17:17:41 30534 search_find: file="/etc/exim4/passwd.client" 17:17:41 30534 key="mail.gmx.net" partial=-1 affix=NULL starflags=0 17:17:41 30534 LRU list: 17:17:41 30534 :/etc/exim4/passwd.client 17:17:41 30534 End 17:17:41 30534 internal_search_find: file="/etc/exim4/passwd.client" 17:17:41 30534 type=nwildlsearch key="mail.gmx.net" 17:17:41 30534 cached data used for lookup of mail.gmx.net 17:17:41 30534 in /etc/exim4/passwd.client 17:17:41 30534 lookup yielded: MYSMTPLOGIN:MYSMTPPASSWORD 17:17:41 30534 expanding: $value 17:17:41 30534 result: MYSMTPLOGIN:MYSMTPPASSWORD 17:17:41 30534 expanding: ${lookup{$host}nwildlsearch{/etc/exim4/passwd.client}{$value}fail} 17:17:41 30534 result: MYSMTPLOGIN:MYSMTPPASSWORD 17:17:41 30534 expanding: \N[\^]\N 17:17:41 30534 result: [\^] 17:17:41 30534 expanding: ^^ 17:17:41 30534 result: ^^ 17:17:41 30534 expanding: ${sg{${lookup{$host}nwildlsearch{/etc/exim4/passwd.client}{$value}fail}}{\N[\^]\N}{^^}} 17:17:41 30534 result: MYSMTPLOGIN:MYSMTPPASSWORD 17:17:41 30534 expanding: $host 17:17:41 30534 result: mail.gmx.net 17:17:41 30534 expanding: /etc/exim4/passwd.client 17:17:41 30534 result: /etc/exim4/passwd.client 17:17:41 30534 search_open: nwildlsearch "/etc/exim4/passwd.client" 17:17:41 30534 cached open 17:17:41 30534 search_find: file="/etc/exim4/passwd.client" 17:17:41 30534 key="mail.gmx.net" partial=-1 affix=NULL starflags=0 17:17:41 30534 LRU list: 17:17:41 30534 :/etc/exim4/passwd.client 17:17:41 30534 End 17:17:41 30534 internal_search_find: file="/etc/exim4/passwd.client" 17:17:41 30534 type=nwildlsearch key="mail.gmx.net" 17:17:41 30534 cached data used for lookup of mail.gmx.net 17:17:41 30534 in /etc/exim4/passwd.client 17:17:41 30534 lookup yielded: MYSMTPLOGIN:MYSMTPPASSWORD 17:17:41 30534 expanding: $value 17:17:41 30534 result: MYSMTPLOGIN:MYSMTPPASSWORD 17:17:41 30534 expanding: ${lookup{$host}nwildlsearch{/etc/exim4/passwd.client}{$value}fail} 17:17:41 30534 result: MYSMTPLOGIN:MYSMTPPASSWORD 17:17:41 30534 expanding: \N[\^]\N 17:17:41 30534 result: [\^] 17:17:41 30534 expanding: ^^ 17:17:41 30534 result: ^^ 17:17:41 30534 expanding: ${sg{${lookup{$host}nwildlsearch{/etc/exim4/passwd.client}{$value}fail}}{\N[\^]\N}{^^}} 17:17:41 30534 result: MYSMTPLOGIN:MYSMTPPASSWORD 17:17:41 30534 expanding: \N([^:]+:)(.*)\N 17:17:41 30534 result: ([^:]+:)(.*) 17:17:41 30534 expanding: \$2 17:17:41 30534 result: $2 17:17:41 30534 expanding: $2 17:17:41 30534 result: MYSMTPPASSWORD 17:17:41 30534 expanding: ^${extract{1}{:}{${sg{${lookup{$host}nwildlsearch{/etc/exim4/passwd.client}{$value}fail}}{\N[\^]\N}{^^}}}}^${sg{${sg{${lookup{$host}nwildlsearch{/etc/exim4/passwd.client}{$value}fail}}{\N[\^]\N}{^^}}}{\N([^:]+:)(.*)\N}{\$2}} 17:17:41 30534 result: ^MYSMTPLOGIN^MYSMTPPASSWORD 17:17:41 30534 expanding: ${if !eq{$tls_out_cipher}{}{^${extract{1}{:}{${sg{${lookup{$host}nwildlsearch{/etc/exim4/passwd.client}{$value}fail}}{\N[\^]\N}{^^}}}}^${sg{${sg{${lookup{$host}nwildlsearch{/etc/exim4/passwd.client}{$value}fail}}{\N[\^]\N}{^^}}}{\N([^:]+:)(.*)\N}{\$2}}}fail} 17:17:41 30534 result: ^MYSMTPLOGIN^MYSMTPPASSWORD 17:17:41 30534 SMTP>> AUTH PLAIN ************************************ 17:17:41 30534 tls_do_write(0xffb1768c, 49) 17:17:41 30534 gnutls_record_send(SSL, 0xffb1768c, 49) 17:17:41 30534 outbytes=49 17:17:41 30534 waiting for data on socket 17:17:41 30534 Calling gnutls_record_recv(0xf7e5e438, 0xffb18a8c, 4096) 17:17:41 30534 read response data: size=30 17:17:41 30534 SMTP<< 235 Authentication succeeded 17:17:41 30534 plain authenticator yielded 0 17:17:41 30534 SMTP>> MAIL FROM:<ametz...@gmx.net> SIZE=1305 17:17:41 30534 tls_do_write(0xffb1768c, 40) 17:17:41 30534 gnutls_record_send(SSL, 0xffb1768c, 40) 17:17:41 30534 outbytes=40 17:17:41 30534 waiting for data on socket 17:17:41 30534 Calling gnutls_record_recv(0xf7e5e438, 0xffb18a8c, 4096) 17:17:41 30534 read response data: size=43 17:17:41 30534 SMTP<< 250 Requested mail action okay, completed 17:17:41 30534 SMTP>> RCPT TO:<ametz...@bebt.de> 17:17:41 30534 tls_do_write(0xffb1768c, 28) 17:17:41 30534 gnutls_record_send(SSL, 0xffb1768c, 28) 17:17:41 30534 outbytes=28 17:17:41 30534 waiting for data on socket 17:17:41 30534 Calling gnutls_record_recv(0xf7e5e438, 0xffb18a8c, 4096) 17:17:41 30534 read response data: size=8 17:17:41 30534 SMTP<< 250 OK 17:17:41 30534 SMTP>> DATA 17:17:41 30534 tls_do_write(0xffb1768c, 6) 17:17:41 30534 gnutls_record_send(SSL, 0xffb1768c, 6) 17:17:41 30534 outbytes=6 17:17:41 30534 waiting for data on socket 17:17:41 30534 Calling gnutls_record_recv(0xf7e5e438, 0xffb18a8c, 4096) 17:17:41 30534 read response data: size=46 17:17:41 30534 SMTP<< 354 Start mail input; end with <CRLF>.<CRLF> 17:17:41 30534 SMTP>> writing message and terminating "." 17:17:41 30534 writing data block fd=7 size=285 timeout=300 17:17:41 30534 tls_do_write(0xf7e507f0, 285) 17:17:41 30534 gnutls_record_send(SSL, 0xf7e507f0, 285) 17:17:41 30534 outbytes=285 17:17:41 30534 waiting for data on socket 17:17:41 30534 Calling gnutls_record_recv(0xf7e5e438, 0xffb18a8c, 4096) 17:17:41 30534 read response data: size=72 17:17:41 30534 SMTP<< 250 Requested mail action okay, completed: id=0MPV69-1W0pOh3bN3-004mUG 17:17:41 30534 journalling ametz...@bebt.de 17:17:41 30534 ok=1 send_quit=1 send_rset=0 continue_more=0 yield=0 first_address is NULL 17:17:41 30534 212.227.17.190 in hosts_nopass_tls? no (option unset) 17:17:41 30534 transport_check_waiting entered 17:17:41 30534 sequence=1 local_max=500 global_max=-1 17:17:41 30534 locking /var/spool/exim4/db/wait-remote_smtp_smarthost.lockfile 17:17:41 30534 locked /var/spool/exim4/db/wait-remote_smtp_smarthost.lockfile 17:17:41 30534 EXIM_DBOPEN(/var/spool/exim4/db/wait-remote_smtp_smarthost) 17:17:41 30534 returned from EXIM_DBOPEN 17:17:41 30534 opened hints database /var/spool/exim4/db/wait-remote_smtp_smarthost: flags=O_RDWR 17:17:41 30534 dbfn_read: key=mail.gmx.net 17:17:41 30534 no messages waiting for mail.gmx.net 17:17:41 30534 SMTP>> QUIT 17:17:41 30534 tls_do_write(0xffb1768c, 6) 17:17:41 30534 gnutls_record_send(SSL, 0xffb1768c, 6) 17:17:41 30534 outbytes=6 17:17:41 30534 tls_close(): shutting down TLS 17:17:41 30534 set_process_info: 30534 delivering 1W4w0C-0007wP-Kq: just tried mail.gmx.net [212.227.17.190] for ametz...@bebt.de: result OK 17:17:41 30534 Leaving remote_smtp_smarthost transport 17:17:41 30534 set_process_info: 30534 delivering 1W4w0C-0007wP-Kq (just run remote_smtp_smarthost for ametz...@bebt.de in subprocess) 17:17:41 30534 search_tidyup called 17:17:41 30532 reading pipe for subprocess 30534 (not ended) 17:17:41 30532 read() yielded 274 17:17:41 30532 Z0 item read 17:17:41 30532 remote delivery process 30534 ended 17:17:41 30532 set_process_info: 30532 delivering 1W4w0C-0007wP-Kq 17:17:41 30532 post-process ametz...@bebt.de (0) 17:17:41 30532 ametz...@bebt.de delivered 17:17:41 30532 LOG: MAIN 17:17:41 30532 => ametz...@bebt.de R=smarthost T=remote_smtp_smarthost H=mail.gmx.net [212.227.17.190] X=TLS1.2:RSA_AES_128_CBC_SHA1:128 DN="C=DE,O=1&1 Mail & Media GmbH,ST=Rhineland-Palatinate,L=Montabaur,EMAIL=server-ce...@1und1.de,CN=mail.gmx.net" A=plain C="250 Requested mail action okay, completed: id=0MPV69-1W0pOh3bN3-004mUG" 17:17:41 30532 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>> 17:17:41 30532 changed uid/gid: post-delivery tidying 17:17:41 30532 uid=102 gid=103 pid=30532 17:17:41 30532 auxiliary group list: <none> 17:17:41 30532 set_process_info: 30532 tidying up after delivering 1W4w0C-0007wP-Kq 17:17:41 30532 Processing retry items 17:17:41 30532 Succeeded addresses: 17:17:41 30532 ametz...@bebt.de: no retry items 17:17:41 30532 Failed addresses: 17:17:41 30532 Deferred addresses: 17:17:41 30532 end of retry processing 17:17:41 30532 LOG: MAIN 17:17:41 30532 Completed 17:17:41 30532 end delivery of 1W4w0C-0007wP-Kq 17:17:41 30532 search_tidyup called 17:17:41 30532 search_tidyup called 17:17:41 30532 >>>>>>>>>>>>>>>> Exim pid=30532 terminating with rc=0 >>>>>>>>>>>>>>>>