Bug#736081: Won't authenticate over STARTTLS without AUTH_CLIENT_ALLOW_NOTLS_PASSWORDS
Andreas Metzler
ametzler at bebt.de
Sun Jan 19 17:40:59 UTC 2014
On 2014-01-19 Juliusz Chroboczek <jch at 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'
-------------- next part --------------
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 ametzler at gmx.net ametzler at 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 = ametzler at gmx.net
17:17:40 30529 set_process_info: 30529 accepting a local non-SMTP message from <ametzler at gmx.net>
17:17:40 30529 Sender: ametzler at gmx.net
17:17:40 30529 Recipients:
17:17:40 30529 ametzler at 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=ametzler at 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 ametzler at gmx.net in "*@+local_domains"? no (end of list)
17:17:40 30529 address match test: subject=ametzler at gmx.net pattern=*@argenau
17:17:40 30529 gmx.net in "argenau"? no (end of list)
17:17:40 30529 ametzler at gmx.net in "*@argenau"? no (end of list)
17:17:40 30529 rewritten sender = ametzler at gmx.net
17:17:40 30529 rewrite_one_header: type=F:
17:17:40 30529 From: ametzler at gmx.net
17:17:40 30529 address match test: subject=ametzler at 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 ametzler at gmx.net in "*@+local_domains"? no (end of list)
17:17:40 30529 address match test: subject=ametzler at gmx.net pattern=*@argenau
17:17:40 30529 gmx.net in "argenau"? no (end of list)
17:17:40 30529 ametzler at 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 at argenau>
17:17:40 30529 F From: ametzler at 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 <ametzler at 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 ametzler at 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 <ametzler at gmx.net>)
17:17:40 30529 id 1W4w0C-0007wP-Kq
17:17:40 30529 for ametzler at 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 <ametzler at gmx.net>)
17:17:40 30529 id 1W4w0C-0007wP-Kq
17:17:40 30529 for ametzler at 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 <= ametzler at 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=ametzler at 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 ametzler at 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: ametzler at bebt.de
17:17:40 30532 unique = ametzler at bebt.de
17:17:40 30532 no domain retry record
17:17:40 30532 no address retry record
17:17:40 30532 ametzler at bebt.de: queued for routing
17:17:40 30532 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:17:40 30532 routing ametzler at 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 ametzler at bebt.de
17:17:40 30532 R: smarthost for ametzler at bebt.de
17:17:40 30532 calling smarthost router
17:17:40 30532 smarthost router called for ametzler at 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: ametzler at 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 ametzler at 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 --------> ametzler at 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 ametzler at 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 ametzler at bebt.de
17:17:40 30534 T: remote_smtp_smarthost for ametzler at bebt.de
17:17:40 30534 remote_smtp_smarthost transport entered
17:17:40 30534 ametzler at 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] (ametzler at bebt.de)
17:17:40 30534 set_process_info: 30534 delivering 1W4w0C-0007wP-Kq to mail.gmx.net [212.227.17.190] (ametzler at 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:<ametzler at 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:<ametzler at 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 ametzler at 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 ametzler at 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 ametzler at 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 ametzler at bebt.de (0)
17:17:41 30532 ametzler at bebt.de delivered
17:17:41 30532 LOG: MAIN
17:17:41 30532 => ametzler at 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-certs at 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 ametzler at 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 >>>>>>>>>>>>>>>>
More information about the Pkg-exim4-maintainers
mailing list