[exim] Diagnosing problems authenticating as a client

Top Page
Delete this message
Reply to this message
Author: Boylan, Ross
Date:  
To: exim users
Subject: [exim] Diagnosing problems authenticating as a client
I am trying to use exim as a client with my school's email provider, microsoft, as the server.
Setups very similar to what I'm using worked a few months ago.

My immediate question is whether the transcript at the bottom gives any clues about the problem. In particular, does the absence of a user account from the transcript mean it is not attempting to login as me? That would be consistent with the error message
530 5.7.57 SMTP; Client was not authenticated to send anonymous mail during MAIL FROM [BYAPR08CA0053.namprd08.prod.outlook.com]

Comments/Theories

1. Despite my "user login not attempted" theory above, a subsequent session with -d+lookup shows the account name and password successfully looked up by the authenticator.

2. Campus has introduced two-factor authentication with Duo (after the usual login you have to give a one-time code, usually received on your cell). I had hoped that wouldn't affect the email over SMTP, but it may have. Since my exim server is not wired up to support this, that would cause a failure. Does the fact that there are apparently two separate transmissions of gibberish at authentication time indicate two different "passwords" are being required? I have a feeling the first one may just be an encoded version of my account name (see concern 1).

3. Toward the end: "cannot use sendfile for body: spoolfile not wireformat". I was trying to send a file saved from mutt. Perhaps it's not in the right format? In that case, the "anonymous mail" might reflect, e.g., a missing envelope sender. Against this a) the login authentication failure happened earlier and b) sending mail from mutt direct to my local exim failed in the same way (and that certainly should have been in the right format).

4. The list of authenticators does not include LOGIN. However, it does have PLAINTEXT, which I imagine is what's used (if that list is relevant at all when exim is the client).

I'm running on Debian buster.

Transcript, with a few edits for convenience and security:

# date; exim -bm -d-all+auth+dns+rewrite+transport+timestamp -f ross@??? -t < ~ross/testmail 
Mon 08 Jul 2019 02:55:41 PM PDT
14:55:41 Exim version 4.92 uid=0 gid=0 pid=1218 D=2a000028
Support for: crypteq iconv() IPv6 GnuTLS move_frozen_messages DANE DKIM DNSSEC Event OCSP PRDR SOCKS TCP_Fast_Open
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
Configure owner: 0:0
Size of off_t: 8
Compiler: GCC [8.3.0]
Library version: Glibc: Compile: 2.28
                        Runtime: 2.28
Library version: BDB: Compile: Berkeley DB 5.3.28: (September  9, 2013)
                      Runtime: Berkeley DB 5.3.28: (September  9, 2013)
Library version: GnuTLS: Compile: 3.6.7
                         Runtime: 3.6.7
Library version: PCRE: Compile: 8.39
                       Runtime: 8.39 2016-06-14
WHITELIST_D_MACROS: "OUTGOING"
TRUSTED_CONFIG_LIST: "/etc/exim4/trusted_configs"
14:55:41 configuration file is /var/lib/exim4/config.autogenerated
14:55:41 log selectors = 0000cffc c6401022 00000001
14:55:41 cwd=/etc/exim4 6 args: exim -bm -d-all+auth+dns+rewrite+transport+timestamp -f ross@??? -t
14:55:41 trusted user
14:55:41 admin user
14:55:41 rewritten sender = ross@???
14:55:41 rewrite_one_header: type=F:
14:55:41   From: Ross Boylan <ross@???>
14:55:41 rewrite_one_header: type=T:
14:55:41   To: rossboylan@???
14:55:41 LOG: MAIN
14:55:41   <= ross@??? U=root P=local S=582
14:55:41 >>>>>>>>>>>>>>>> Exim pid=1218 (main) terminating with rc=0 >>>>>>>>>>>>>>>>
14:55:41 Exim version 4.92 uid=118 gid=124 pid=1219 D=2a000028
[config info repeated here]
14:55:41 admin user
14:55:41 R: smarthost for rossboylan@???
14:55:42 >>>>>>>>>>>>>>>> Remote deliveries >>>>>>>>>>>>>>>>
14:55:42 --------> rossboylan@??? <--------
14:55:42 T: remote_smtp_smarthost for rossboylan@???
14:55:42 remote_smtp_smarthost transport entered
14:55:42   rossboylan@???
14:55:42 hostlist:
14:55:42   'SJC-efz.ms-acdc.office.com' IP 52.96.3.178 port 587
14:55:42   'SJC-efz.ms-acdc.office.com' IP 40.97.220.34 port 587
14:55:42   'SJC-efz.ms-acdc.office.com' IP 52.96.36.82 port 587
14:55:42   'SJC-efz.ms-acdc.office.com' IP 52.96.36.114 port 587
14:55:42 checking status of SJC-efz.ms-acdc.office.com
14:55:42 no host retry record
14:55:42 no message retry record
14:55:42 SJC-efz.ms-acdc.office.com [52.96.3.178]:587 retry-status = usable
14:55:42 delivering 1hkbbp-0000Je-JW to SJC-efz.ms-acdc.office.com [52.96.3.178] (rossboylan@???)
14:55:42 Transport port=25 replaced by host-specific port=587
14:55:42 Connecting to SJC-efz.ms-acdc.office.com [52.96.3.178]:587 ... connected
14:55:43 read response data: size=110
14:55:43   SMTP<< 220 BYAPR04CA0001.outlook.office365.com Microsoft ESMTP MAIL Service ready at Mon, 8 Jul 2019 21:55:42 +0000
14:55:43   SMTP>> EHLO barley.betterworld.us
14:55:43 cmd buf flush 28 bytes
14:55:43 read response data: size=204
14:55:43   SMTP<< 250-BYAPR04CA0001.outlook.office365.com Hello [66.181.128.6]
14:55:43          250-SIZE 157286400
14:55:43          250-PIPELINING
14:55:43          250-DSN
14:55:43          250-ENHANCEDSTATUSCODES
14:55:43          250-STARTTLS
14:55:43          250-8BITMIME
14:55:43          250-BINARYMIME
14:55:43          250-CHUNKING
14:55:43          250 SMTPUTF8
14:55:43   SMTP>> STARTTLS
14:55:43 cmd buf flush 10 bytes
14:55:43 read response data: size=29
14:55:43   SMTP<< 220 2.0.0 SMTP server ready
14:55:44   SMTP>> EHLO barley.betterworld.us
14:55:44 cmd buf flush 28 bytes
14:55:44 read response data: size=214
14:55:44   SMTP<< 250-BYAPR04CA0001.outlook.office365.com Hello [66.181.128.6]
14:55:44          250-SIZE 157286400
14:55:44          250-PIPELINING
14:55:44          250-DSN
14:55:44          250-ENHANCEDSTATUSCODES
14:55:44          250-AUTH LOGIN XOAUTH2
14:55:44          250-8BITMIME
14:55:44          250-BINARYMIME
14:55:44          250-CHUNKING
14:55:44          250 SMTPUTF8
14:55:44 using PIPELINING
14:55:44 CHUNKING usable
14:55:44 using DSN
14:55:44 scanning authentication mechanisms
14:55:44   SMTP>> AUTH LOGIN
14:55:44 cmd buf flush 12 bytes
14:55:44 read response data: size=18
14:55:44   SMTP<< 334 [gibberish]
14:55:44   SMTP>> ****************************
14:55:44 cmd buf flush 30 bytes
14:55:44 read response data: size=18
14:55:44   SMTP<< 334 [different gibberish]
14:55:44   SMTP>> ************************
14:55:44 cmd buf flush 26 bytes
14:55:50 read response data: size=81
14:55:50   SMTP<< 535 5.7.3 Authentication unsuccessful [BYAPR04CA0001.namprd04.prod.outlook.com]
14:55:50 login authenticator yielded 2
14:55:50 LOG: MAIN
14:55:50   login authenticator failed H=SJC-efz.ms-acdc.office.com [52.96.3.178] 535 5.7.3 Authentication unsuccessful [BYAPR04CA0001.namprd04.prod.outlook.com]
14:55:50   SMTP>> MAIL FROM:<Ross.Boylan@???> SIZE=1623
14:55:50   SMTP>> RCPT TO:<rossboylan@???>
14:55:50          will write message using CHUNKING
14:55:50 rewrite_one_header: type=F:
14:55:50   From: Ross Boylan <ross@???>
14:55:50 LOG: address_rewrite MAIN
14:55:50   "ross@???" from from: rewritten as "Ross.Boylan@???" by rule 1
14:55:50 newlen=41 newtype=F newtext:
14:55:50 From: Ross Boylan <Ross.Boylan@???>
14:55:50 remainder: 
14:55:50 rewrite_one_header: type=T:
14:55:50   To: rossboylan@???
14:55:50 LOG: address_rewrite MAIN
14:55:50   "rossboylan@???" from to: rewritten as "Ross.Boylan@???" by rule 1
14:55:50 newlen=25 newtype=T newtext:
14:55:50 To: Ross.Boylan@???
14:55:50 remainder: 
14:55:50   SMTP>> BDAT 585 LAST
14:55:50 cmd buf flush 100 bytes (more expected)
14:55:50 cannot use sendfile for body: spoolfile not wireformat
14:55:50 writing data block fd=6 size=585 timeout=300
14:55:50 sync_responses expect mail
14:55:55 read response data: size=129
14:55:55   SMTP<< 530 5.7.57 SMTP; Client was not authenticated to send anonymous mail during MAIL FROM [BYAPR04CA0001.namprd04.prod.outlook.com]
14:55:55 bad response for MAIL
14:55:55 LOG: MAIN
14:55:55   H=SJC-efz.ms-acdc.office.com [52.96.3.178] TLS error on connection (recv): The TLS connection was non-properly terminated.
14:55:55   SMTP(No such file or directory)<<
14:55:55 ok=0 send_quit=1 send_rset=1 continue_more=0 yield=0 first_address is NULL
14:55:55   SMTP>> QUIT
14:55:55 cmd buf flush 6 bytes
14:55:55 LOG: MAIN
14:55:55   H=SJC-efz.ms-acdc.office.com [52.96.3.178] TLS error on connection (send): The specified session has been invalidated for some reason.
14:55:55 send failed: No such file or directory
14:55:55   SMTP(close)>>
14:55:55 Leaving remote_smtp_smarthost transport
14:55:55 LOG: MAIN
14:55:55   ** rossboylan@??? R=smarthost T=remote_smtp_smarthost H=SJC-efz.ms-acdc.office.com [52.96.3.178] X=TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256 CV=no DN="C=US,ST=Washington,L=Redmond,O=Microsoft Corporation,CN=outlook.com": SMTP error from remote mail server after pipelined end of data: 530 5.7.57 SMTP; Client was not authenticated to send anonymous mail during MAIL FROM [BYAPR04CA0001.namprd04.prod.outlook.com]
14:55:55 cannot use sendfile for body: spoolfile not wireformat
14:55:55 writing data block fd=8 size=624 timeout=0
14:55:55 Exim version 4.92 uid=118 gid=124 pid=1225 D=2a000028
Support for: crypteq iconv() IPv6 GnuTLS move_frozen_messages DANE DKIM DNSSEC Event OCSP PRDR SOCKS TCP_Fast_Open
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