[exim] exim _only_ fails to authenticate/send if using MUA, …

Αρχική Σελίδα
Delete this message
Reply to this message
Συντάκτης: snowcrash+exim-users
Ημερομηνία:  
Προς: exim-users
Αντικείμενο: [exim] exim _only_ fails to authenticate/send if using MUA, mail to self ... ?
i've an exim 4.64 server

    Exim version 4.64 #1 built 07-Dec-2006 09:44:17
    Copyright (c) University of Cambridge 2006
    Berkeley DB: Berkeley DB 4.5.20: (October 25, 2006)
    Support for: crypteq PAM TCPwrappers OpenSSL Content_Scanning
Old_Demime Experimental_DomainKeys
    Lookups: lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmnz dsearch mysql
    Authenticators: cram_md5 dovecot plaintext
    Routers: accept dnslookup ipliteral manualroute queryprogram redirect
    Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
    Fixed never_users: 0
    Size of off_t: 8
    Configuration file is /var/mailserver/exim/exim.conf


installed on,

    mail.localdomain.com


i've verified that i can successfully:

    (1)    @ shell(mail.localdomain.com)
        % exim -v snowcrash@???
        --> message is RECEIVED in INBOX


    (2)    @ shell(mail.localdomain.com)
        % exim -v snowcrash@???
        --> message is RECEIVED in INBOX


    (3)    @ MUA(mail.localdomain.com)
            from: snowcrash@???
            to:   snowcrash@???
        --> message is RECEIVED in INBOX


but, if i,

    (4)    @ MUA(mail.localdomain.com)
            from: snowcrash@???
            to:   snowcrash@???


the MUA reports,

    waiting for Server Response
    Authenticating to Server


and 'waits' there forever --
-- the message never gets sent/delivered.

in my exim log, with exim launched as,

    exim ... -d+all


and config'd as,

    log_selector = +all


i see only,

    21:35:27 25737 Connection request from 192.168.1.6 port 55143
    21:35:27 25737 interface address=192.168.1.5 port=25
    21:35:27 25737 LOG: smtp_connection MAIN
    21:35:27 25737   SMTP connection from [192.168.1.6]:55143
I=[192.168.1.5]:25 (TCP/IP connection count = 1)
    21:35:27 25737 search_tidyup called
    21:35:27 25737 1 SMTP accept process running
    21:35:27 25737 Listening...
    21:35:27 26417 sender_fullhost = [192.168.1.6]:55143
    21:35:27 26417 sender_rcvhost = [192.168.1.6] (port=55143)
    21:35:27 26417 Process 26417 is handling incoming connection from
[192.168.1.6]:55143
    21:35:27 26417 checking for IP options
    21:35:27 26417 no IP options found
    21:35:27 26417 host in host_lookup? yes (matched "*")
    21:35:27 26417 looking up host name for 192.168.1.6
    ;; res_querydomain(6.1.168.192.in-addr.arpa, <Nil>, 1, 12)
    ;; res_query(6.1.168.192.in-addr.arpa, 1, 12)
    ;; res_mkquery(0, 6.1.168.192.in-addr.arpa, 1, 12)
    ;; res_send()
    ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 13026
    ;; flags: rd; Ques: 1, Ans: 0, Auth: 0, Addit: 0
    ;; QUESTIONS:
    ;;      6.1.168.192.in-addr.arpa, type = PTR, class = IN

    
    ;; Querying server (# 1) address = 192.168.1.5
    ;; got answer:
    ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 13026
    ;; flags: qr aa rd ra; Ques: 1, Ans: 1, Auth: 1, Addit: 1
    ;; QUESTIONS:
    ;;      6.1.168.192.in-addr.arpa, type = PTR, class = IN

    
    ;; ANSWERS:
    6.1.168.192.in-addr.arpa.       86400   IN      PTR
desktop.localdomain.com.

    
    ;; AUTHORITY RECORDS:
    1.168.192.in-addr.arpa. 86400   IN      NS      mail.localdomain.com.

    
    ;; ADDITIONAL RECORDS:
    mail.localdomain.com.     86400   IN      A       192.168.1.5

    
    21:35:27 26417 DNS lookup of 6.1.168.192.in-addr.arpa (PTR) succeeded
    21:35:27 26417 IP address lookup yielded desktop.localdomain.com
    21:35:27 26417 gethostbyname looked up these IP addresses:
    21:35:27 26417   name=desktop.localdomain.com address=192.168.1.6
    21:35:27 26417 checking addresses for desktop.localdomain.com
    21:35:27 26417   192.168.1.6 OK
    21:35:27 26417 sender_fullhost = desktop.localdomain.com [192.168.1.6]:55143
    21:35:27 26417 sender_rcvhost = desktop.localdomain.com ([192.168.1.6]:55143)
    21:35:27 26417 set_process_info: 26417 handling incoming connection
from desktop.localdomain.com [192.168.1.6]:55143 I=[192.168.1.5]:25
    21:35:27 26417 host in host_reject_connection? no (option unset)
    21:35:27 26417 host in sender_unqualified_hosts? no (end of list)
    21:35:27 26417 host in recipient_unqualified_hosts? no (end of list)
    21:35:27 26417 host in helo_verify_hosts? no (option unset)
    21:35:27 26417 host in helo_try_verify_hosts? yes (matched "*")
    21:35:27 26417 host in helo_accept_junk_hosts? no (option unset)
    21:35:27 26417 using ACL "acl_check_connect"
    21:35:27 26417 processing "warn"
    21:35:27 26417 expanding: $tod_epoch
    21:35:27 26417    result: 1166160927
    21:35:27 26417 check set acl_m2 = $tod_epoch
    21:35:27 26417                  = 1166160927
    21:35:27 26417 warn: condition test succeeded
    21:35:27 26417 processing "accept"
    21:35:27 26417 check hosts = : +relay_from_hosts
    21:35:27 26417 host in "192.168.1.0/28
:dbm;/var/mailserver/exim/domains.nearby.dbm"? yes (matched
"192.168.1.0/28")
    21:35:27 26417 host in ": +relay_from_hosts"? yes (matched "+relay_from_hosts")
    21:35:27 26417 accept: condition test succeeded
    21:35:27 26417 expanding: $smtp_active_hostname ESMTP $tod_full
    21:35:27 26417    result: mail.localdomain.com ESMTP Thu, 14 Dec 2006
21:35:27 -0800
    21:35:27 26417 SMTP>> 220 mail.localdomain.com ESMTP Thu, 14 Dec 2006
21:35:27 -0800
    21:35:27 26417 Process 26417 is ready for new message
    21:35:27 26417 smtp_setup_msg entered
    21:35:27 26417 SMTP<< EHLO [192.168.1.6]
    21:35:27 26417 sender_fullhost = desktop.localdomain.com [192.168.1.6]:55143
    21:35:27 26417 sender_rcvhost = desktop.localdomain.com ([192.168.1.6]:55143)
    21:35:27 26417 set_process_info: 26417 handling incoming connection
from desktop.localdomain.com [192.168.1.6]:55143 I=[192.168.1.5]:25
    21:35:27 26417 verifying EHLO/HELO argument "[192.168.1.6]"
    21:35:27 26417 matched host address
    21:35:27 26417 using ACL "acl_check_helo"
    21:35:27 26417 processing "warn"
    21:35:27 26417 expanding: $tod_epoch
    21:35:27 26417    result: 1166160927
    21:35:27 26417 check set acl_m2 = $tod_epoch
    21:35:27 26417                  = 1166160927
    21:35:27 26417 warn: condition test succeeded
    21:35:27 26417 processing "accept"
    21:35:27 26417 check hosts = : +relay_from_hosts
    21:35:27 26417 cached yes match for +relay_from_hosts
    21:35:27 26417 cached lookup data = NULL
    21:35:27 26417 host in ": +relay_from_hosts"? yes (matched
"+relay_from_hosts" - cached)
    21:35:27 26417 accept: condition test succeeded
    21:35:27 26417 host in pipelining_advertise_hosts? yes (matched "*")
    21:35:27 26417 expanding: $tls_cipher
    21:35:27 26417    result:
    21:35:27 26417 expanding:
    21:35:27 26417    result:
    21:35:27 26417 condition: eq{$tls_cipher}{}
    21:35:27 26417    result: true
    21:35:27 26417 expanding:
    21:35:27 26417    result:
    21:35:27 26417 expanding: *
    21:35:27 26417    result: *
    21:35:27 26417 skipping: result is not used
    21:35:27 26417 expanding: ${if eq{$tls_cipher}{}{}{*}}
    21:35:27 26417    result:
    21:35:27 26417 host in auth_advertise_hosts? no (end of list)
    21:35:27 26417 host in tls_advertise_hosts? yes (matched "*")
    21:35:27 26417 SMTP>> 250-mail.localdomain.com Hello
desktop.localdomain.com [192.168.1.6]
    21:35:27 26417 250-SIZE 52428800
    21:35:27 26417 250-8BITMIME
    21:35:27 26417 250-PIPELINING
    21:35:27 26417 250-STARTTLS
    21:35:27 26417 250 HELP
    21:35:27 26417 SMTP<< STARTTLS
    21:35:27 26417 tls_certificate file
/var/mailserver/exim/mail.localdomain.com.cert.rsa.pem
    21:35:27 26417 tls_privatekey file
/var/mailserver/exim/mail.localdomain.com.privkey.rsa.pem
    21:35:27 26417 Initialized TLS
    21:35:27 26417 host in tls_verify_hosts? no (option unset)
    21:35:27 26417 host in tls_try_verify_hosts? yes (matched "*")
    21:35:27 26417 SMTP>> 220 TLS go ahead
    21:35:27 26417 Calling SSL_accept
    21:35:27 26417 SSL info: before/accept initialization
    21:35:27 26417 SSL info: before/accept initialization
    21:35:27 26417 SSL info: SSLv3 read client hello A
    21:35:27 26417 SSL info: SSLv3 write server hello A
    21:35:27 26417 SSL info: SSLv3 write certificate A
    21:35:27 26417 SSL info: SSLv3 write certificate request A
    21:35:27 26417 SSL info: SSLv3 flush data
    21:35:27 26417 SSL info: SSLv3 read client certificate A
    21:35:27 26417 SSL info: SSLv3 read client key exchange A
    21:35:27 26417 SSL info: SSLv3 read finished A
    21:35:27 26417 SSL info: SSLv3 write change cipher spec A
    21:35:27 26417 SSL info: SSLv3 write finished A
    21:35:27 26417 SSL info: SSLv3 flush data
    21:35:27 26417 SSL info: SSL negotiation finished successfully
    21:35:27 26417 SSL info: SSL negotiation finished successfully
    21:35:27 26417 SSL_accept was successful
    21:35:27 26417 Cipher: TLSv1:AES256-SHA:256
    21:35:27 26417 Shared ciphers:
DHE-RSA-AES256-SHA:DHE-DSS-AES256-SHA:AES256-SHA:EDH-RSA-DES-CBC3-SHA:EDH-DSS-DES-CBC3-SHA:DES-CBC3-SHA:DHE-RSA-AES128-SHA:DHE-DSS-AES128-SHA:AES128-SHA:RC4-SHA:RC4-MD5:EDH-RSA-DES-CBC-SHA:EDH-DSS-DES-CBC-SHA:DES-CBC-SHA:EXP-EDH-RSA-DES-CBC-SHA:EXP-EDH-DSS-DES-CBC-SHA:EXP-DES-CBC-SHA:EXP-RC2-CBC-MD5:EXP-RC4-MD5
    21:35:27 26417 sender_fullhost = desktop.localdomain.com [192.168.1.6]:55143
    21:35:27 26417 sender_rcvhost = desktop.localdomain.com ([192.168.1.6]:55143)
    21:35:27 26417 set_process_info: 26417 handling incoming TLS
connection from desktop.localdomain.com [192.168.1.6]:55143
I=[192.168.1.5]:25
    21:35:27 26417 TLS active
    21:35:27 26417 Calling SSL_read(110d100, 1815a00, 4096)
    21:35:27 26417 SMTP<< EHLO [192.168.1.6]
    21:35:27 26417 sender_fullhost = desktop.localdomain.com [192.168.1.6]:55143
    21:35:27 26417 sender_rcvhost = desktop.localdomain.com ([192.168.1.6]:55143)
    21:35:27 26417 set_process_info: 26417 handling TLS incoming
connection from desktop.localdomain.com [192.168.1.6]:55143
I=[192.168.1.5]:25
    21:35:27 26417 verifying EHLO/HELO argument "[192.168.1.6]"
    21:35:27 26417 matched host address
    21:35:27 26417 using ACL "acl_check_helo"
    21:35:27 26417 processing "warn"
    21:35:27 26417 expanding: $tod_epoch
    21:35:27 26417    result: 1166160927
    21:35:27 26417 check set acl_m2 = $tod_epoch
    21:35:27 26417                  = 1166160927
    21:35:27 26417 warn: condition test succeeded
    21:35:27 26417 processing "accept"
    21:35:27 26417 check hosts = : +relay_from_hosts
    21:35:27 26417 cached yes match for +relay_from_hosts
    21:35:27 26417 cached lookup data = NULL
    21:35:27 26417 host in ": +relay_from_hosts"? yes (matched
"+relay_from_hosts" - cached)
    21:35:27 26417 accept: condition test succeeded
    21:35:27 26417 host in pipelining_advertise_hosts? yes (matched "*")
    21:35:27 26417 expanding: $tls_cipher
    21:35:27 26417    result: TLSv1:AES256-SHA:256
    21:35:27 26417 expanding:
    21:35:27 26417    result:
    21:35:27 26417 condition: eq{$tls_cipher}{}
    21:35:27 26417    result: false
    21:35:27 26417 expanding:
    21:35:27 26417    result:
    21:35:27 26417 skipping: result is not used
    21:35:27 26417 expanding: *
    21:35:27 26417    result: *
    21:35:27 26417 expanding: ${if eq{$tls_cipher}{}{}{*}}
    21:35:27 26417    result: *
    21:35:27 26417 host in auth_advertise_hosts? yes (matched "*")
    21:35:27 26417 expanding:
    21:35:27 26417    result:
    21:35:27 26417 expanding: $tls_cipher
    21:35:27 26417    result: TLSv1:AES256-SHA:256
    21:35:27 26417 condition: !eq{}{$tls_cipher}
    21:35:27 26417    result: true
    21:35:27 26417 expanding: ${if !eq{}{$tls_cipher}}
    21:35:27 26417    result: true
    21:35:27 26417 tls_do_write(1811010, 166)
    21:35:27 26417 SSL_write(SSL, 1811010, 166)
    21:35:27 26417 outbytes=166 error=0
    21:35:27 26417 SMTP>> 250-mail.localdomain.com Hello
desktop.localdomain.com [192.168.1.6]
    21:35:27 26417 250-SIZE 52428800
    21:35:27 26417 250-8BITMIME
    21:35:27 26417 250-PIPELINING
    21:35:27 26417 250-AUTH PLAIN CRAM-MD5 DIGEST-MD5
    21:35:27 26417 250 HELP
    21:35:27 26417 Calling SSL_read(110d100, 1815a00, 4096)
    21:35:27 26417 SMTP<< AUTH PLAIN
AGJsYWtlcnNAbWFpbC5wZ25ldHdvcmsubmV0AHRVbU8hMVJBVA==
    21:35:27 26417 dovecot authentication
    21:35:27 26417 received: VERSION        1       0
    21:35:27 26417 received: SPID   26191


and nothing further. :-/

i'm stumped as to why the _other_ send tests are OK, but not the
self-to-self-via-MUA.

to my eye -- no doubt mistaken -- i see nothing wrong in the log
above. i know i've missed something.

any ideas?

thanks.