Bug#297174: exim4+libgnutls11: TLS error (gnutls_handshake)
Michael Biebl
Michael Biebl <biebl@teco.edu>, 297174@bugs.debian.org
Fri, 11 Mar 2005 16:07:21 +0100
This is an OpenPGP/MIME signed message (RFC 2440 and 3156)
--------------enig4213A6191E2F308F937E1A8B
Content-Type: multipart/mixed;
boundary="------------000603000702090008090804"
This is a multi-part message in MIME format.
--------------000603000702090008090804
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
Andreas Metzler wrote:
> On 2005-02-27 Michael Biebl <biebl@teco.edu> wrote:
> [...]
>
> I am quite mystified by this. - Can you test with debugging enabled?
>
Hi Andreas,
I tested with debugging enabled and attached the results. I can only
trigger the failure if I use a MUA (in my case Thunderbird) but not with
"openssl s_client".
As the log file doesn't contain much additional information I started to
investigate the problem a little bit further. This is what I found so far:
Setup to reproduce this bug:
- Configure NSS/pam to use ldap (over SSL).
Relevant configuration files:
/etc/nsswitch.conf
passwd: files ldap
group: files ldap
shadow: files ldap
/etc/pam_ldap.conf
base dc=test,dc=com
uri ldaps://server.test.com/ (note the "s")
ldap_version 3
/etc/libnss-ldap.conf
base dc=test,dc=com
uri ldaps://server.test.com/ (note the "s")
ldap_version 3
Optionally adapt /etc/common-* to use LDAP (for authentication over pam)
auth sufficient pam_ldap.so
auth required pam_unix.so try_first_pass
Next step: Configure exim4 to allow authentication only over SSL
Under section "Authentication" add the following:
plain_pam:
driver = plaintext
public_name = PLAIN
server_prompts = :
server_advertise_condition = ${if eq{$tls_cipher}{}{0}{1}}
server_condition = ${if pam{$2:${sg{$3}{:}{::}}}{yes}{no}}
server_set_id = $2
login_pam:
driver = plaintext
public_name = LOGIN
server_advertise_condition = ${if eq{$tls_cipher}{}{0}{1}}
server_prompts = "Username:: : Password::"
server_condition = ${if pam{$1:${sg{$2}{:}{::}}}{yes}{no}}
server_set_id = $1
Note: Any other authenticator that requires TLS should work too.
If you start exim4 with this setup it should trigger the aformentioned
bug: a gnutls_handshake error on every second connection attempt.
So as a next step I recompiled exim4 and gnutls11 with debugging
information enabled. If I now start the exim4 server process the
gnutls_handshake function is called the first time during startup.
The backtrace looks like this:
main() exim.c:3922
daemon_go() daemon.c:1447
exim_setugid() exim.c:520
...
libnss_ldaps.so.2
...
libldap.so.2
...
gnutls_handshake.c gnutls_handshake.c:1897
So the libgnutls11 lib is not directly called by exim4 but through NSS/PAM.
On a connection attempt a child process is forked and a TLS session is
started. This time exim4 uses the libgnutls11 lib directly
(tls_server_start():3209 smtp_in.c). tls_server_start() calls
gnutls_handshake and this is the point where it fails. The exact
location is in the _gnutls_handshake_server function between STATE3 and
STATE4. As I'm not a TLS guru I can't exactly tell what is going wrong
here. My guess is that gnutls is not reentrant or not correctly
initialized when it is used a second time. This would also explain why
it works if I link exim4 against the older libgnutls10. That way NSS/PAM
uses libgnutls11 and exim4 itself the older libgnutls10.
Could you please confirm that you can reproduce the bug! Any ideas what
is going wrong here? If you need more information or if you have ideas
what I could try next to find the culprit please let me know.
Thanks,
Michael
--
------------------------------------------------------------
E-Mail: biebl@teco.edu
WWW: http://www.teco.edu/
TecO (Telecooperation Office) Vincenz-Priessnitz-Str.1
University of Karlsruhe 76131 Karlsruhe, Germany
------------------------------------------------------------
--------------000603000702090008090804
Content-Type: text/plain;
name="exim4.debug.tls"
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="exim4.debug.tls"
Exim version 4.50 uid=0 gid=0 pid=6444 D=fbb95cfd
Berkeley DB: Sleepycat Software: Berkeley DB 4.2.52: (December 3, 2003)
Support for: iconv() IPv6 PAM Perl GnuTLS Content_Scanning Old_Demime
Lookups: lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmnz dnsdb dsearch ldap ldapdn ldapm mysql nis nis0 passwd pgsql
Authenticators: cram_md5 cyrus_sasl plaintext spa
Routers: accept dnslookup ipliteral iplookup manualroute queryprogram redirect
Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
Fixed never_users: 0
changed uid/gid: forcing real = effective
uid=0 gid=0 pid=6444
auxiliary group list: <none>
configuration file is /var/lib/exim4/config.autogenerated
log selectors = 00000ffc 00060800
trusted user
admin user
user name "root" extracted from gecos field "root"
originator: uid=0 gid=0 login=root name=root
6444 listening on all interfaces (IPv6) port 25
6444 listening on all interfaces (IPv4) port 25
6444 pid written to /var/run/exim4/exim.pid
6444 changed uid/gid: running as a daemon
6444 uid=108 gid=108 pid=6444
6444 auxiliary group list: 45 108
6444 LOG: MAIN
6444 exim 4.50 daemon started: pid=6444, no queue runs, listening for SMTP on port 25 (IPv6 and IPv4)
6444 set_process_info: 6444 daemon: no queue runs, listening for SMTP on port 25 (IPv6 and IPv4)
6444 daemon running with uid=108 gid=108 euid=108 egid=108
6444 Listening...
6444 Connection request from 127.0.0.1 port 56109
6444 search_tidyup called
6444 1 SMTP accept process running
6444 Listening...
6446 sender_fullhost = [127.0.0.1]
6446 sender_rcvhost = [127.0.0.1]
6446 Process 6446 is handling incoming connection from [127.0.0.1]
6446 host in host_lookup? yes (matched "*")
6446 looking up host name for 127.0.0.1
6446 DNS lookup of 1.0.0.127.in-addr.arpa (PTR) succeeded
6446 IP address lookup yielded loopback
6446 gethostbyname2(af=inet6) returned 1 (HOST_NOT_FOUND)
6446 gethostbyname2(af=inet) returned 1 (HOST_NOT_FOUND)
6446 no IP address found for host loopback (during SMTP connection from [127.0.0.1])
6446 LOG: host_lookup_failed MAIN
6446 no IP address found for host loopback (during SMTP connection from [127.0.0.1])
6446 no IP addresses found for loopback
6446 127.0.0.1 does not match any IP address for loopback
6446 sender_fullhost = [127.0.0.1]
6446 sender_rcvhost = [127.0.0.1]
6446 set_process_info: 6446 handling incoming connection from [127.0.0.1]
6446 host in host_reject_connection? no (option unset)
6446 host in sender_unqualified_hosts? no (option unset)
6446 host in recipient_unqualified_hosts? no (option unset)
6446 host in helo_verify_hosts? no (option unset)
6446 host in helo_try_verify_hosts? no (option unset)
6446 host in helo_accept_junk_hosts? no (option unset)
6446 SMTP>> 220 localhost ESMTP Exim 4.50 Fri, 11 Mar 2005 15:03:47 +0100
6446 Process 6446 is ready for new message
6446 smtp_setup_msg entered
6446 SMTP<< EHLO [127.0.0.1]
6446 [127.0.0.1] in helo_lookup_domains? yes (matched "@[]")
6446 looking up host name for 127.0.0.1
6446 DNS lookup of 1.0.0.127.in-addr.arpa (PTR) succeeded
6446 IP address lookup yielded loopback
6446 gethostbyname2(af=inet6) returned 1 (HOST_NOT_FOUND)
6446 gethostbyname2(af=inet) returned 1 (HOST_NOT_FOUND)
6446 no IP address found for host loopback (during SMTP connection from [127.0.0.1])
6446 LOG: host_lookup_failed MAIN
6446 no IP address found for host loopback (during SMTP connection from [127.0.0.1])
6446 no IP addresses found for loopback
6446 127.0.0.1 does not match any IP address for loopback
6446 sender_fullhost = ([127.0.0.1]) [127.0.0.1]
6446 sender_rcvhost = [127.0.0.1] (helo=[127.0.0.1])
6446 set_process_info: 6446 handling incoming connection from ([127.0.0.1]) [127.0.0.1]
6446 host in pipelining_advertise_hosts? yes (matched "*")
6446 host in auth_advertise_hosts? yes (matched "*")
6446 host in tls_advertise_hosts? yes (matched "*")
6446 SMTP>> 250-localhost Hello [127.0.0.1] [127.0.0.1]
6446 250-SIZE 52428800
6446 250-PIPELINING
6446 250-STARTTLS
6446 250 HELP
6446 SMTP<< STARTTLS
6446 initializing GnuTLS as a server
6446 read RSA and D-H parameters from file
6446 initialized RSA and D-H parameters
6446 certificate file = /etc/exim4/exim.crt
6446 key file = /etc/exim4/exim.key
6446 initialized certificate stuff
6446 host in tls_verify_hosts? no (option unset)
6446 host in tls_try_verify_hosts? no (option unset)
6446 initialized GnuTLS session
6446 SMTP>> 220 TLS go ahead
6446 gnutls_handshake was successful
6446 cipher: TLS-1.0:DHE_RSA_AES_256_CBC_SHA:32
6446 sender_fullhost = [127.0.0.1]
6446 sender_rcvhost = [127.0.0.1]
6446 set_process_info: 6446 handling incoming TLS connection from [127.0.0.1]
6446 TLS active
6446 Calling gnutls_record_recv(81abf08, 81b91a0, 4096)
6446 SMTP<< EHLO [127.0.0.1]
6446 [127.0.0.1] in helo_lookup_domains? yes (matched "@[]")
6446 looking up host name for 127.0.0.1
6446 DNS lookup of 1.0.0.127.in-addr.arpa (PTR) succeeded
6446 IP address lookup yielded loopback
6446 gethostbyname2(af=inet6) returned 1 (HOST_NOT_FOUND)
6446 gethostbyname2(af=inet) returned 1 (HOST_NOT_FOUND)
6446 no IP address found for host loopback (during SMTP connection from [127.0.0.1])
6446 LOG: host_lookup_failed MAIN
6446 no IP address found for host loopback (during SMTP connection from [127.0.0.1])
6446 no IP addresses found for loopback
6446 127.0.0.1 does not match any IP address for loopback
6446 sender_fullhost = ([127.0.0.1]) [127.0.0.1]
6446 sender_rcvhost = [127.0.0.1] (helo=[127.0.0.1])
6446 set_process_info: 6446 handling TLS incoming connection from ([127.0.0.1]) [127.0.0.1]
6446 host in pipelining_advertise_hosts? yes (matched "*")
6446 host in auth_advertise_hosts? yes (matched "*")
6446 tls_do_write(81283e8, 112)
6446 gnutls_record_send(SSL, 81283e8, 112)
6446 outbytes=112
6446 SMTP>> 250-localhost Hello [127.0.0.1] [127.0.0.1]
6446 250-SIZE 52428800
6446 250-PIPELINING
6446 250-AUTH PLAIN LOGIN
6446 250 HELP
6446 Calling gnutls_record_recv(81abf08, 81b91a0, 4096)
6446 SMTP<< AUTH PLAIN AGJpZWJsAGJpOTdtaTIx
6446 Running PAM authentication for user "user"
6446 PAM success
6446 plain_pam authenticator:
6446 $1 =
6446 $2 = user
6446 $3 = secret
6446 expanded string: yes
6446 SMTP>> 235 Authentication succeeded
6446 tls_do_write(811f080, 30)
6446 gnutls_record_send(SSL, 811f080, 30)
6446 outbytes=30
6446 Calling gnutls_record_recv(81abf08, 81b91a0, 4096)
6446 SMTP<< MAIL FROM:<michael@milchstrasse.xx> SIZE=444
6446 spool directory space = 2064176K inodes = 897612 check_space = 0K inodes = 0 msg_size = 5444
6446 SMTP>> 250 OK
6446 tls_do_write(811f080, 8)
6446 gnutls_record_send(SSL, 811f080, 8)
6446 outbytes=8
6446 Calling gnutls_record_recv(81abf08, 81b91a0, 4096)
6446 SMTP<< RCPT TO:<root@milchstrasse.xx>
6446 using ACL "acl_check_rcpt"
6446 processing "accept"
6446 check hosts = :
6446 host in ":"? no (end of list)
6446 accept: condition test failed
6446 processing "warn"
6446 check hosts = +relay_from_hosts
6446 host in "127.0.0.1 : ::::1 :"? yes (matched "127.0.0.1")
6446 host in "+relay_from_hosts"? yes (matched "+relay_from_hosts")
6446 check control = submission/sender_retain
6446 warn: condition test succeeded
6446 processing "deny"
6446 check domains = +local_domains
6446 milchstrasse.xx in "@:localhost:milchstrasse.xx"? yes (matched "milchstrasse.xx")
6446 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains")
6446 check local_parts = ^[.] : ^.*[@%!/|\'`#&?]
6446 root in "^[.] : ^.*[@%!/|'`#&?]"? no (end of list)
6446 deny: condition test failed
6446 processing "deny"
6446 check domains = !+local_domains
6446 cached yes match for +local_domains
6446 cached lookup data = NULL
6446 milchstrasse.xx in "!+local_domains"? no (matched "!+local_domains" - cached)
6446 deny: condition test failed
6446 processing "accept"
6446 check local_parts = postmaster
6446 root in "postmaster"? no (end of list)
6446 accept: condition test failed
6446 processing "deny"
6446 check !acl = acl_whitelist_local_deny
6446 using ACL "acl_whitelist_local_deny"
6446 processing "accept"
6446 check hosts = ${if exists{/etc/exim4/local_host_whitelist}{/etc/exim4/local_host_whitelist}{}}
6446 host in ""? no (end of list)
6446 accept: condition test failed
6446 processing "accept"
6446 check senders = ${if exists{/etc/exim4/local_sender_whitelist}{/etc/exim4/local_sender_whitelist}{}}
6446 michael@milchstrasse.xx in ""? no (end of list)
6446 accept: condition test failed
6446 end of ACL "acl_whitelist_local_deny": implicit DENY
6446 check senders = ${if exists{/etc/exim4/local_sender_blacklist}{/etc/exim4/local_sender_blacklist}{}}
6446 michael@milchstrasse.xx in ""? no (end of list)
6446 deny: condition test failed
6446 processing "deny"
6446 check !acl = acl_whitelist_local_deny
6446 using ACL "acl_whitelist_local_deny"
6446 processing "accept"
6446 check hosts = ${if exists{/etc/exim4/local_host_whitelist}{/etc/exim4/local_host_whitelist}{}}
6446 host in ""? no (end of list)
6446 accept: condition test failed
6446 processing "accept"
6446 check senders = ${if exists{/etc/exim4/local_sender_whitelist}{/etc/exim4/local_sender_whitelist}{}}
6446 michael@milchstrasse.xx in ""? no (end of list)
6446 accept: condition test failed
6446 end of ACL "acl_whitelist_local_deny": implicit DENY
6446 check hosts = ${if exists{/etc/exim4/local_host_blacklist}{/etc/exim4/local_host_blacklist}{}}
6446 host in ""? no (end of list)
6446 deny: condition test failed
6446 processing "accept"
6446 check domains = +local_domains
6446 cached yes match for +local_domains
6446 cached lookup data = NULL
6446 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains" - cached)
6446 check verify = recipient
6446 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
6446 Verifying root@milchstrasse.xx
6446 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
6446 Considering root@milchstrasse.xx
6446 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
6446 routing root@milchstrasse.xx
6446 --------> hubbed_hosts router <--------
6446 local_part=root domain=milchstrasse.xx
6446 checking domains
6446 expansion of "${if exists{/etc/exim4/hubbed_hosts}{partial-lsearch;/etc/exim4/hubbed_hosts}fail}" forced failure: assume not in this list
6446 hubbed_hosts router skipped: domains mismatch
6446 --------> dnslookup_relay_to_domains router <--------
6446 local_part=root domain=milchstrasse.xx
6446 checking domains
6446 cached yes match for +local_domains
6446 cached lookup data = NULL
6446 milchstrasse.xx in "! +local_domains : +relay_to_domains"? no (matched "! +local_domains" - cached)
6446 dnslookup_relay_to_domains router skipped: domains mismatch
6446 --------> dnslookup router <--------
6446 local_part=root domain=milchstrasse.xx
6446 checking domains
6446 cached yes match for +local_domains
6446 cached lookup data = NULL
6446 milchstrasse.xx in "! +local_domains"? no (matched "! +local_domains" - cached)
6446 dnslookup router skipped: domains mismatch
6446 --------> real_local router <--------
6446 local_part=root domain=milchstrasse.xx
6446 real_local router skipped: prefix mismatch
6446 --------> system_aliases router <--------
6446 local_part=root domain=milchstrasse.xx
6446 checking domains
6446 cached yes match for +local_domains
6446 cached lookup data = NULL
6446 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains" - cached)
6446 R: system_aliases for root@milchstrasse.xx
6446 calling system_aliases router
6446 rda_interpret (string): ${lookup{$local_part}lsearch{/etc/aliases}}
6446 search_open: lsearch "/etc/aliases"
6446 search_find: file="/etc/aliases"
6446 key="root" partial=-1 affix=NULL starflags=0
6446 LRU list:
6446 :/etc/aliases
6446 End
6446 internal_search_find: file="/etc/aliases"
6446 type=lsearch key="root"
6446 file lookup required for root
6446 in /etc/aliases
6446 lookup yielded: michael
6446 expanded: michael
6446 file is not a filter file
6446 parse_forward_list: michael
6446 extract item: michael
6446 system_aliases router generated michael@milchstrasse.xx
6446 errors_to=NULL transport=NULL
6446uid=unset gid=unset home=NULL
6446 routed by system_aliases router
6446 envelope to: root@milchstrasse.xx
6446 transport: <none>
6446 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
6446 Considering michael@milchstrasse.xx
6446 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
6446 routing michael@milchstrasse.xx
6446 --------> hubbed_hosts router <--------
6446 local_part=michael domain=milchstrasse.xx
6446 checking domains
6446 expansion of "${if exists{/etc/exim4/hubbed_hosts}{partial-lsearch;/etc/exim4/hubbed_hosts}fail}" forced failure: assume not in this list
6446 hubbed_hosts router skipped: domains mismatch
6446 --------> dnslookup_relay_to_domains router <--------
6446 local_part=michael domain=milchstrasse.xx
6446 checking domains
6446 milchstrasse.xx in "@:localhost:milchstrasse.xx"? yes (matched "milchstrasse.xx")
6446 milchstrasse.xx in "! +local_domains : +relay_to_domains"? no (matched "! +local_domains")
6446 dnslookup_relay_to_domains router skipped: domains mismatch
6446 --------> dnslookup router <--------
6446 local_part=michael domain=milchstrasse.xx
6446 checking domains
6446 cached yes match for +local_domains
6446 cached lookup data = NULL
6446 milchstrasse.xx in "! +local_domains"? no (matched "! +local_domains" - cached)
6446 dnslookup router skipped: domains mismatch
6446 --------> real_local router <--------
6446 local_part=michael domain=milchstrasse.xx
6446 real_local router skipped: prefix mismatch
6446 --------> system_aliases router <--------
6446 local_part=michael domain=milchstrasse.xx
6446 checking domains
6446 cached yes match for +local_domains
6446 cached lookup data = NULL
6446 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains" - cached)
6446 R: system_aliases for michael@milchstrasse.xx
6446 calling system_aliases router
6446 rda_interpret (string): ${lookup{$local_part}lsearch{/etc/aliases}}
6446 search_open: lsearch "/etc/aliases"
6446 cached open
6446 search_find: file="/etc/aliases"
6446 key="michael" partial=-1 affix=NULL starflags=0
6446 LRU list:
6446 :/etc/aliases
6446 End
6446 internal_search_find: file="/etc/aliases"
6446 type=lsearch key="michael"
6446 file lookup required for michael
6446 in /etc/aliases
6446 lookup failed
6446 expanded:
6446 file is not a filter file
6446 parse_forward_list:
6446 system_aliases router declined for michael@milchstrasse.xx
6446 --------> userforward router <--------
6446 local_part=michael domain=milchstrasse.xx
6446 userforward router skipped: verify 2 0 0
6446 --------> procmail router <--------
6446 local_part=michael domain=milchstrasse.xx
6446 procmail router skipped: verify 2 0 0
6446 --------> maildrop router <--------
6446 local_part=michael domain=milchstrasse.xx
6446 maildrop router skipped: verify 2 0 0
6446 --------> local_user router <--------
6446 local_part=michael domain=milchstrasse.xx
6446 checking domains
6446 cached yes match for +local_domains
6446 cached lookup data = NULL
6446 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains" - cached)
6446 checking local_parts
6446 michael in "! root"? yes (end of list)
6446 checking for local user
6446 R: local_user for michael@milchstrasse.xx
6446 calling local_user router
6446 local_user router called for michael@milchstrasse.xx
6446 domain = milchstrasse.xx
6446 set transport mail_spool
6446 queued for mail_spool transport: local_part = michael
6446 domain = milchstrasse.xx
6446 errors_to=NULL
6446 domain_data=NULL localpart_data=NULL
6446 routed by local_user router
6446 envelope to: michael@milchstrasse.xx
6446 transport: mail_spool
6446 ----------- end verify ------------
6446 accept: condition test succeeded
6446 SMTP>> 250 Accepted
6446 tls_do_write(811f080, 14)
6446 gnutls_record_send(SSL, 811f080, 14)
6446 outbytes=14
6446 Calling gnutls_record_recv(81abf08, 81b91a0, 4096)
6446 SMTP<< DATA
6446 SMTP>> 354 Enter message, ending with "." on a line by itself
6446 tls_do_write(811f080, 56)
6446 gnutls_record_send(SSL, 811f080, 56)
6446 outbytes=56
6446 search_tidyup called
6446 Calling gnutls_record_recv(81abf08, 81b91a0, 4096)
6446 host in ignore_fromline_hosts? no (option unset)
6446 >>Headers received:
6446 Message-ID: <4231A533.9090208@milchstrasse.xx>
6446 Date: Fri, 11 Mar 2005 15:03:31 +0100
6446 From: Michael Biebl <michael@milchstrasse.xx>
6446 User-Agent: Debian Thunderbird 1.0 (X11/20050116)
6446 X-Accept-Language: en-us, en
6446 MIME-Version: 1.0
6446 To: root@milchstrasse.xx
6446 Subject: test
6446 X-Enigmail-Version: 0.90.0.0
6446 X-Enigmail-Supports: pgp-inline, pgp-mime
6446 Content-Type: text/plain; charset=UTF-8; format=flowed
6446 Content-Transfer-Encoding: 7bit
6446
6446 address match: subject=michael@milchstrasse.xx pattern=*@+local_domains
6446 milchstrasse.xx in "@:localhost:milchstrasse.xx"? yes (matched "milchstrasse.xx")
6446 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains")
6446 michael@milchstrasse.xx in "*@+local_domains"? yes (matched "*@+local_domains")
6446 search_open: lsearch "/etc/email-addresses"
6446 search_find: file="/etc/email-addresses"
6446 key="michael" partial=-1 affix=NULL starflags=0
6446 LRU list:
6446 :/etc/email-addresses
6446 End
6446 internal_search_find: file="/etc/email-addresses"
6446 type=lsearch key="michael"
6446 file lookup required for michael
6446 in /etc/email-addresses
6446 lookup failed
6446 address match: subject=michael@milchstrasse.xx pattern=*@milchstrasse.xx
6446 milchstrasse.xx in "milchstrasse.xx"? yes (matched "milchstrasse.xx")
6446 michael@milchstrasse.xx in "*@milchstrasse.xx"? yes (matched "*@milchstrasse.xx")
6446 search_open: lsearch "/etc/email-addresses"
6446 cached open
6446 search_find: file="/etc/email-addresses"
6446 key="michael" partial=-1 affix=NULL starflags=0
6446 LRU list:
6446 :/etc/email-addresses
6446 End
6446 internal_search_find: file="/etc/email-addresses"
6446 type=lsearch key="michael"
6446 cached data used for lookup of michael
6446 in /etc/email-addresses
6446 lookup failed
6446 rewritten sender = michael@milchstrasse.xx
6446 rewrite_one_header: type=F:
6446 From: Michael Biebl <michael@milchstrasse.xx>
6446 address match: subject=michael@milchstrasse.xx pattern=*@+local_domains
6446 milchstrasse.xx in "@:localhost:milchstrasse.xx"? yes (matched "milchstrasse.xx")
6446 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains")
6446 michael@milchstrasse.xx in "*@+local_domains"? yes (matched "*@+local_domains")
6446 search_open: lsearch "/etc/email-addresses"
6446 cached open
6446 search_find: file="/etc/email-addresses"
6446 key="michael" partial=-1 affix=NULL starflags=0
6446 LRU list:
6446 :/etc/email-addresses
6446 End
6446 internal_search_find: file="/etc/email-addresses"
6446 type=lsearch key="michael"
6446 cached data used for lookup of michael
6446 in /etc/email-addresses
6446 lookup failed
6446 address match: subject=michael@milchstrasse.xx pattern=*@milchstrasse.xx
6446 milchstrasse.xx in "milchstrasse.xx"? yes (matched "milchstrasse.xx")
6446 michael@milchstrasse.xx in "*@milchstrasse.xx"? yes (matched "*@milchstrasse.xx")
6446 search_open: lsearch "/etc/email-addresses"
6446 cached open
6446 search_find: file="/etc/email-addresses"
6446 key="michael" partial=-1 affix=NULL starflags=0
6446 LRU list:
6446 :/etc/email-addresses
6446 End
6446 internal_search_find: file="/etc/email-addresses"
6446 type=lsearch key="michael"
6446 cached data used for lookup of michael
6446 in /etc/email-addresses
6446 lookup failed
6446 rewrite_one_header: type=T:
6446 To: root@milchstrasse.xx
6446 search_tidyup called
6446 >>Headers after rewriting and local additions:
6446 I Message-ID: <4231A533.9090208@milchstrasse.xx>
6446 Date: Fri, 11 Mar 2005 15:03:31 +0100
6446 F From: Michael Biebl <michael@milchstrasse.xx>
6446 User-Agent: Debian Thunderbird 1.0 (X11/20050116)
6446 X-Accept-Language: en-us, en
6446 MIME-Version: 1.0
6446 T To: root@milchstrasse.xx
6446 Subject: test
6446 X-Enigmail-Version: 0.90.0.0
6446 X-Enigmail-Supports: pgp-inline, pgp-mime
6446 Content-Type: text/plain; charset=UTF-8; format=flowed
6446 Content-Transfer-Encoding: 7bit
6446
6446 Data file written for message 1D9kk1-0001fy-5y
6446 >>Generated Received: header line
6446 P Received: from [127.0.0.1] (helo=[127.0.0.1])
6446 by localhost with esmtpsa (TLS-1.0:DHE_RSA_AES_256_CBC_SHA:32)
6446 (Exim 4.50)
6446 id 1D9kk1-0001fy-5y
6446 for root@milchstrasse.xx; Fri, 11 Mar 2005 15:03:49 +0100
6446 using ACL "acl_check_data"
6446 processing "accept"
6446 accept: condition test succeeded
6446 calling local_scan(); timeout=300
6446 local_scan() returned 0 NULL
6446 Writing spool header file
6446 Size of headers = 629
6446 LOG: MAIN
6446 <= michael@milchstrasse.xx H=([127.0.0.1]) [127.0.0.1] P=esmtpsa X=TLS-1.0:DHE_RSA_AES_256_CBC_SHA:32 A=plain_pam:user S=632 id=4231A533.9090208@milchstrasse.xx
6446 SMTP>> 250 OK id=1D9kk1-0001fy-5y
6446 tls_do_write(811f080, 28)
6446 gnutls_record_send(SSL, 811f080, 28)
6446 outbytes=28
6446 search_tidyup called
6446 Sender: michael@milchstrasse.xx
6446 Recipients:
6446 root@milchstrasse.xx
6447 exec /usr/sbin/exim4 -d=0xfbbd5cfd -Mc 1D9kk1-0001fy-5y
6447 Exim version 4.50 uid=108 gid=108 pid=6447 D=fbbd5cfd
Berkeley DB: Sleepycat Software: Berkeley DB 4.2.52: (December 3, 2003)
Support for: iconv() IPv6 PAM Perl GnuTLS Content_Scanning Old_Demime
Lookups: lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmnz dnsdb dsearch ldap ldapdn ldapm mysql nis nis0 passwd pgsql
Authenticators: cram_md5 cyrus_sasl plaintext spa
Routers: accept dnslookup ipliteral iplookup manualroute queryprogram redirect
Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
Fixed never_users: 0
6447 changed uid/gid: forcing real = effective
6447 uid=0 gid=108 pid=6447
6447 auxiliary group list: <none>
6446 forked delivery process 6447
6446 Process 6446 is ready for new message
6446 smtp_setup_msg entered
6446 Calling gnutls_record_recv(81abf08, 81b91a0, 4096)
6446 SMTP<< QUIT
6446 SMTP>> 221 localhost closing connection
6446 tls_do_write(811f080, 34)
6446 gnutls_record_send(SSL, 811f080, 34)
6446 outbytes=34
6446 tls_close(): shutting down TLS
6446 LOG: smtp_connection MAIN
6446 SMTP connection from ([127.0.0.1]) [127.0.0.1] closed by QUIT
6446 search_tidyup called
6444 child 6446 ended: status=0x0
6444 0 SMTP accept processes now running
6444 Listening...
6447 configuration file is /var/lib/exim4/config.autogenerated
6447 log selectors = 00000ffc 00060800
6447 trusted user
6447 admin user
6447 skipping ACL configuration - not needed
6447 set_process_info: 6447 delivering specified messages
6447 set_process_info: 6447 delivering 1D9kk1-0001fy-5y
6447 reading spool file 1D9kk1-0001fy-5y-H
6447 user=root uid=0 gid=0 sender=michael@milchstrasse.xx
6447 sender_fullhost = ([127.0.0.1]) [127.0.0.1]
6447 sender_rcvhost = [127.0.0.1] (helo=[127.0.0.1])
6447 sender_local=0 ident=unset
6447 Non-recipients:
6447 Empty Tree
6447 ---- End of tree ----
6447 recipients_count=1
6447 body_linecount=2 message_linecount=17
6447 Delivery address list:
6447 root@milchstrasse.xx
6447 locking /var/spool/exim4/db/retry.lockfile
6447 locked /var/spool/exim4/db/retry.lockfile
6447 no retry data available
6447 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
6447 Considering: root@milchstrasse.xx
6447 unique = root@milchstrasse.xx
6447 no domain retry record
6447 no address retry record
6447 root@milchstrasse.xx: queued for routing
6447 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
6447 routing root@milchstrasse.xx
6447 --------> hubbed_hosts router <--------
6447 local_part=root domain=milchstrasse.xx
6447 checking domains
6447 expansion of "${if exists{/etc/exim4/hubbed_hosts}{partial-lsearch;/etc/exim4/hubbed_hosts}fail}" forced failure: assume not in this list
6447 hubbed_hosts router skipped: domains mismatch
6447 --------> dnslookup_relay_to_domains router <--------
6447 local_part=root domain=milchstrasse.xx
6447 checking domains
6447 milchstrasse.xx in "@:localhost:milchstrasse.xx"? yes (matched "milchstrasse.xx")
6447 milchstrasse.xx in "! +local_domains : +relay_to_domains"? no (matched "! +local_domains")
6447 dnslookup_relay_to_domains router skipped: domains mismatch
6447 --------> dnslookup router <--------
6447 local_part=root domain=milchstrasse.xx
6447 checking domains
6447 cached yes match for +local_domains
6447 cached lookup data = NULL
6447 milchstrasse.xx in "! +local_domains"? no (matched "! +local_domains" - cached)
6447 dnslookup router skipped: domains mismatch
6447 --------> real_local router <--------
6447 local_part=root domain=milchstrasse.xx
6447 real_local router skipped: prefix mismatch
6447 --------> system_aliases router <--------
6447 local_part=root domain=milchstrasse.xx
6447 checking domains
6447 cached yes match for +local_domains
6447 cached lookup data = NULL
6447 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains" - cached)
6447 R: system_aliases for root@milchstrasse.xx
6447 calling system_aliases router
6447 rda_interpret (string): ${lookup{$local_part}lsearch{/etc/aliases}}
6447 search_open: lsearch "/etc/aliases"
6447 search_find: file="/etc/aliases"
6447 key="root" partial=-1 affix=NULL starflags=0
6447 LRU list:
6447 :/etc/aliases
6447 End
6447 internal_search_find: file="/etc/aliases"
6447 type=lsearch key="root"
6447 file lookup required for root
6447 in /etc/aliases
6447 lookup yielded: michael
6447 expanded: michael
6447 file is not a filter file
6447 parse_forward_list: michael
6447 extract item: michael
6447 system_aliases router generated michael@milchstrasse.xx
6447 errors_to=NULL transport=NULL
6447 uid=unset gid=unset home=NULL
6447 routed by system_aliases router
6447 envelope to: root@milchstrasse.xx
6447 transport: <none>
6447 locking /var/spool/exim4/db/retry.lockfile
6447 locked /var/spool/exim4/db/retry.lockfile
6447 no retry data available
6447 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
6447 Considering: michael@milchstrasse.xx
6447 unique = michael@milchstrasse.xx
6447 no domain retry record
6447 no address retry record
6447 michael@milchstrasse.xx: queued for routing
6447 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
6447 routing michael@milchstrasse.xx
6447 --------> hubbed_hosts router <--------
6447 local_part=michael domain=milchstrasse.xx
6447 checking domains
6447 expansion of "${if exists{/etc/exim4/hubbed_hosts}{partial-lsearch;/etc/exim4/hubbed_hosts}fail}" forced failure: assume not in this list
6447 hubbed_hosts router skipped: domains mismatch
6447 --------> dnslookup_relay_to_domains router <--------
6447 local_part=michael domain=milchstrasse.xx
6447 checking domains
6447 milchstrasse.xx in "@:localhost:milchstrasse.xx"? yes (matched "milchstrasse.xx")
6447 milchstrasse.xx in "! +local_domains : +relay_to_domains"? no (matched "! +local_domains")
6447 dnslookup_relay_to_domains router skipped: domains mismatch
6447 --------> dnslookup router <--------
6447 local_part=michael domain=milchstrasse.xx
6447 checking domains
6447 cached yes match for +local_domains
6447 cached lookup data = NULL
6447 milchstrasse.xx in "! +local_domains"? no (matched "! +local_domains" - cached)
6447 dnslookup router skipped: domains mismatch
6447 --------> real_local router <--------
6447 local_part=michael domain=milchstrasse.xx
6447 real_local router skipped: prefix mismatch
6447 --------> system_aliases router <--------
6447 local_part=michael domain=milchstrasse.xx
6447 checking domains
6447 cached yes match for +local_domains
6447 cached lookup data = NULL
6447 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains" - cached)
6447 R: system_aliases for michael@milchstrasse.xx
6447 calling system_aliases router
6447 rda_interpret (string): ${lookup{$local_part}lsearch{/etc/aliases}}
6447 search_open: lsearch "/etc/aliases"
6447 cached open
6447 search_find: file="/etc/aliases"
6447 key="michael" partial=-1 affix=NULL starflags=0
6447 LRU list:
6447 :/etc/aliases
6447 End
6447 internal_search_find: file="/etc/aliases"
6447 type=lsearch key="michael"
6447 file lookup required for michael
6447 in /etc/aliases
6447 lookup failed
6447 expanded:
6447 file is not a filter file
6447 parse_forward_list:
6447 system_aliases router declined for michael@milchstrasse.xx
6447 --------> userforward router <--------
6447 local_part=michael domain=milchstrasse.xx
6447 checking domains
6447 cached yes match for +local_domains
6447 cached lookup data = NULL
6447 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains" - cached)
6447 checking for local user
6447 R: userforward for michael@milchstrasse.xx
6447 calling userforward router
6447 rda_interpret (file): $home/.forward
6447 expanded: /home/michael/.forward
6447 stat(/home/michael/.)=0
6447 /home/michael/.forward does not exist
6447 userforward router declined for michael@milchstrasse.xx
6447 --------> procmail router <--------
6447 local_part=michael domain=milchstrasse.xx
6447 checking domains
6447 cached yes match for +local_domains
6447 cached lookup data = NULL
6447 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains" - cached)
6447 checking for local user
6447 finduser used cached passwd data for michael
6447 R: procmail for michael@milchstrasse.xx
6447 checking require_files
6447 finduser used cached passwd data for michael
6447 check subsequent files for access by michael
6447 file check: ${if exists{/etc/procmailrc}{/etc/procmailrc}{${home}/.procmailrc}}
6447 expanded file: /home/michael/.procmailrc
6447 stat() yielded -1
6447 errno = 2
6447 procmail router skipped: file check
6447 --------> maildrop router <--------
6447 local_part=michael domain=milchstrasse.xx
6447 checking domains
6447 cached yes match for +local_domains
6447 cached lookup data = NULL
6447 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains" - cached)
6447 checking for local user
6447 finduser used cached passwd data for michael
6447 R: maildrop for michael@milchstrasse.xx
6447 checking require_files
6447 finduser used cached passwd data for michael
6447 check subsequent files for access by michael
6447 file check: ${home}/.mailfilter
6447 expanded file: /home/michael/.mailfilter
6447 stat() yielded -1
6447 errno = 2
6447 maildrop router skipped: file check
6447 --------> local_user router <--------
6447 local_part=michael domain=milchstrasse.xx
6447 checking domains
6447 cached yes match for +local_domains
6447 cached lookup data = NULL
6447 milchstrasse.xx in "+local_domains"? yes (matched "+local_domains" - cached)
6447 checking local_parts
6447 michael in "! root"? yes (end of list)
6447 checking for local user
6447 finduser used cached passwd data for michael
6447 R: local_user for michael@milchstrasse.xx
6447 calling local_user router
6447 local_user router called for michael@milchstrasse.xx
6447 domain = milchstrasse.xx
6447 set transport mail_spool
6447 queued for mail_spool transport: local_part = michael
6447 domain = milchstrasse.xx
6447 errors_to=NULL
6447 domain_data=NULL localpart_data=NULL
6447 routed by local_user router
6447 envelope to: michael@milchstrasse.xx
6447 transport: mail_spool
6447 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
6447 After routing:
6447 Local deliveries:
6447 michael@milchstrasse.xx
6447 Remote deliveries:
6447 Failed addresses:
6447 Deferred addresses:
6447 search_tidyup called
6447 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
6447 --------> michael@milchstrasse.xx <--------
6447 locking /var/spool/exim4/db/retry.lockfile
6447 locked /var/spool/exim4/db/retry.lockfile
6447 no retry data available
6447 search_tidyup called
6448 changed uid/gid: local delivery to michael <michael@milchstrasse.xx> transport=mail_spool
6448 uid=1000 gid=8 pid=6448
6448 auxiliary group list: <none>
6448 home=/home/michael current=/home/michael
6448 set_process_info: 6448 delivering 1D9kk1-0001fy-5y to michael using mail_spool
6448 T: appendfile for michael@milchstrasse.xx
6448 appendfile transport entered
6448 appendfile: mode=660 notify_comsat=0 quota=0 warning=0
6448 file=/var/mail/michael format=unix
6448 message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
6448 message_suffix=\n
6448 maildir_use_size_file=no
6448 locking by lockfile fcntl
6448 lock name: /var/mail/michael.lock
6448 hitch name: /var/mail/michael.lock.localhost.4231a545.00001930
6448 lock file created
6448 mailbox /var/mail/michael is locked
6448 writing to file /var/mail/michael
6448 writing data block fd=9 size=54 timeout=0
6448 writing data block fd=9 size=752 timeout=0
6448 writing data block fd=9 size=1 timeout=0
6448 appendfile yields 0 with errno=0 more_errno=0
6447 journalling michael@milchstrasse.xx
6448 search_tidyup called
6447 mail_spool transport returned OK for michael@milchstrasse.xx
6447 post-process michael@milchstrasse.xx (0)
6447 michael@milchstrasse.xx delivered
6447 root@milchstrasse.xx: children all complete
6447 LOG: MAIN
6447 => michael <root@milchstrasse.xx> R=local_user T=mail_spool
6447 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
6447 changed uid/gid: post-delivery tidying
6447 uid=108 gid=108 pid=6447
6447 auxiliary group list: <none>
6447 set_process_info: 6447 tidying up after delivering 1D9kk1-0001fy-5y
6447 Processing retry items
6447 Succeeded addresses:
6447 michael@milchstrasse.xx: no retry items
6447 root@milchstrasse.xx: no retry items
6447 root@milchstrasse.xx: no retry items
6447 Failed addresses:
6447 Deferred addresses:
6447 end of retry processing
6447 LOG: MAIN
6447 Completed
6447 end delivery of 1D9kk1-0001fy-5y
6447 search_tidyup called
6447 search_tidyup called
6447 >>>>>>>>>>>>>>>> Exim pid=6447 terminating with rc=0 >>>>>>>>>>>>>>>>
6444 Connection request from 127.0.0.1 port 56111
6444 search_tidyup called
6444 1 SMTP accept process running
6444 Listening...
6450 sender_fullhost = [127.0.0.1]
6450 sender_rcvhost = [127.0.0.1]
6450 Process 6450 is handling incoming connection from [127.0.0.1]
6450 host in host_lookup? yes (matched "*")
6450 looking up host name for 127.0.0.1
6450 DNS lookup of 1.0.0.127.in-addr.arpa (PTR) succeeded
6450 IP address lookup yielded loopback
6450 gethostbyname2(af=inet6) returned 1 (HOST_NOT_FOUND)
6450 gethostbyname2(af=inet) returned 1 (HOST_NOT_FOUND)
6450 no IP address found for host loopback (during SMTP connection from [127.0.0.1])
6450 LOG: host_lookup_failed MAIN
6450 no IP address found for host loopback (during SMTP connection from [127.0.0.1])
6450 no IP addresses found for loopback
6450 127.0.0.1 does not match any IP address for loopback
6450 sender_fullhost = [127.0.0.1]
6450 sender_rcvhost = [127.0.0.1]
6450 set_process_info: 6450 handling incoming connection from [127.0.0.1]
6450 host in host_reject_connection? no (option unset)
6450 host in sender_unqualified_hosts? no (option unset)
6450 host in recipient_unqualified_hosts? no (option unset)
6450 host in helo_verify_hosts? no (option unset)
6450 host in helo_try_verify_hosts? no (option unset)
6450 host in helo_accept_junk_hosts? no (option unset)
6450 SMTP>> 220 localhost ESMTP Exim 4.50 Fri, 11 Mar 2005 15:04:08 +0100
6450 Process 6450 is ready for new message
6450 smtp_setup_msg entered
6450 SMTP<< EHLO [127.0.0.1]
6450 [127.0.0.1] in helo_lookup_domains? yes (matched "@[]")
6450 looking up host name for 127.0.0.1
6450 DNS lookup of 1.0.0.127.in-addr.arpa (PTR) succeeded
6450 IP address lookup yielded loopback
6450 gethostbyname2(af=inet6) returned 1 (HOST_NOT_FOUND)
6450 gethostbyname2(af=inet) returned 1 (HOST_NOT_FOUND)
6450 no IP address found for host loopback (during SMTP connection from [127.0.0.1])
6450 LOG: host_lookup_failed MAIN
6450 no IP address found for host loopback (during SMTP connection from [127.0.0.1])
6450 no IP addresses found for loopback
6450 127.0.0.1 does not match any IP address for loopback
6450 sender_fullhost = ([127.0.0.1]) [127.0.0.1]
6450 sender_rcvhost = [127.0.0.1] (helo=[127.0.0.1])
6450 set_process_info: 6450 handling incoming connection from ([127.0.0.1]) [127.0.0.1]
6450 host in pipelining_advertise_hosts? yes (matched "*")
6450 host in auth_advertise_hosts? yes (matched "*")
6450 host in tls_advertise_hosts? yes (matched "*")
6450 SMTP>> 250-localhost Hello [127.0.0.1] [127.0.0.1]
6450 250-SIZE 52428800
6450 250-PIPELINING
6450 250-STARTTLS
6450 250 HELP
6450 SMTP<< STARTTLS
6450 initializing GnuTLS as a server
6450 read RSA and D-H parameters from file
6450 initialized RSA and D-H parameters
6450 certificate file = /etc/exim4/exim.crt
6450 key file = /etc/exim4/exim.key
6450 initialized certificate stuff
6450 host in tls_verify_hosts? no (option unset)
6450 host in tls_try_verify_hosts? no (option unset)
6450 initialized GnuTLS session
6450 SMTP>> 220 TLS go ahead
6450 LOG: MAIN
6450 TLS error on connection from ([127.0.0.1]) [127.0.0.1] (gnutls_handshake): A TLS fatal alert has been received.
6450 TLS failed to start
6450 LOG: smtp_connection MAIN
6450 SMTP connection from ([127.0.0.1]) [127.0.0.1] closed by EOF
6450 search_tidyup called
6444 child 6450 ended: status=0x0
6444 0 SMTP accept processes now running
6444 Listening...
--------------000603000702090008090804--
--------------enig4213A6191E2F308F937E1A8B
Content-Type: application/pgp-signature; name="signature.asc"
Content-Description: OpenPGP digital signature
Content-Disposition: attachment; filename="signature.asc"
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.0 (GNU/Linux)
Comment: Using GnuPG with Thunderbird - http://enigmail.mozdev.org
iD8DBQFCMbQth7PER70FhVQRAvvVAKCztzGyLZQzqRNpDiFidJNSsQ193ACgtJnc
fvTxVNhYaYBod9njmZziqdg=
=fDjQ
-----END PGP SIGNATURE-----
--------------enig4213A6191E2F308F937E1A8B--