Exim not always sending AUTH LOGIN username/password

Question

We are sending mail using exim (configured through WHM). With the same exact configuration, seemingly most of the time exim sends the correct AUTH LOGIN username and password, however sometimes it is omitting this part and sendgrid is refusing with the following error:

host smtp.sendgrid.net [158.85.10.138]
SMTP error from remote mail server after MAIL FROM:<info@*******.net> SIZE=2048:
550 Unauthenticated senders not allowed

Digging into it, I can reproduce the problem (not every time, sometimes) with the following:

# exim -v **@****.com
From: **@****.com
To: **@****.com
Subject: Test exim

This is an exim test.

These are the exim configuration settings:

Section: AUTH

sendgrid_login:
  driver = plaintext
  public_name = LOGIN
  client_send = : ******** : **************

Section: ROUTERSTART

send_via_sendgrid:
  driver = manualroute
  domains = ! +local_domains
  transport = sendgrid_smtp
  route_list = "* smtp.sendgrid.net::587 byname"
  host_find_failed = defer
  no_more

Section: TRANSPORTSTART

sendgrid_smtp:
  driver = smtp
  hosts = smtp.sendgrid.net
  hosts_require_auth = smtp.sendgrid.net
  hosts_require_tls = smtp.sendgrid.net
  authenticated_sender_force = true

When it works, this is the log:

LOG: MAIN
  cwd=/home/** 3 args: exim -v **@****.com
From: **@****.com
To: **@****.com
Subject: Test exim

This is an exim test.
LOG: MAIN
  <= **@****-**.com U=jf P=local S=354 T="Test exim"
**@****-** [~]# LOG: MAIN
  cwd=/var/spool/exim 4 args: /usr/sbin/exim -v -Mc 1ZjWZy-0005re-S3
delivering 1ZjWZy-0005re-S3
Transport port=25 replaced by host-specific port=587
Connecting to smtp.sendgrid.net [198.37.144.212]:587 ... connected
  SMTP<< 220 ismtpd-064 ESMTP service ready
  SMTP>> EHLO **.****-**.com
  SMTP<< 250-**.***.26.157
         250-SIZE 20480000
         250-STARTTLS
         250-AUTH PLAIN LOGIN
         250-8BITMIME
         250-PIPELINING
         250 AUTH=PLAIN LOGIN
  SMTP>> STARTTLS
  SMTP<< 220 Begin TLS negotiation now
  SMTP>> EHLO **.****-**.com
  SMTP<< 250-**.***.26.157
         250-8BITMIME
         250-SIZE 20480000
         250-AUTH=PLAIN LOGIN
         250-AUTH PLAIN LOGIN
         250 PIPELINING
  SMTP>> AUTH LOGIN
  SMTP<< 334 VXNlcm5hbWU6
  SMTP>> ****
  SMTP<< 334 UGFzc3dvcmQ6
  SMTP>> ********************
  SMTP<< 235 Authentication successful.
  SMTP>> MAIL FROM:<**@****-**.com> SIZE=1388 AUTH=**@****-**.com
  SMTP>> RCPT TO:<**@****.com>
  SMTP>> DATA
  SMTP<< 250 Sender address accepted
  SMTP<< 250 Recipient address accepted
  SMTP<< 354 Continue
  SMTP>> writing message and terminating "."
  SMTP<< 250 Delivery in progress
  SMTP>> QUIT
LOG: MAIN
  => **@****.com R=send_via_sendgrid T=sendgrid_smtp H=smtp.sendgrid.net [198.37.144.212] X=TLSv1.2:AES128-GCM-SHA256:128 A=sendgrid_login C="250 Delivery in progress"
LOG: MAIN
  Completed

Pay special attention to the line SMTP>> AUTH LOGIN and the six right below, ending in the 235 Authentication successful. line.

Here is a failure:

LOG: MAIN
  cwd=/home/** 3 args: exim -v **@****.com
From: **@****.com
To: **@****.com
Subject: Test exim

This is an exim test.
LOG: MAIN
  <= **@****-**.com U=jf P=local S=340 T="Test exim"
**@****-** [~]# LOG: MAIN
  cwd=/var/spool/exim 4 args: /usr/sbin/exim -v -Mc 1ZjWjO-0006T8-Eq
delivering 1ZjWjO-0006T8-Eq
Transport port=25 replaced by host-specific port=587
Connecting to smtp.sendgrid.net [198.37.144.225]:587 ... connected
  SMTP<< 220 ismtpd-078 ESMTP service ready
  SMTP>> EHLO ****-**.com
  SMTP<< 250-**.***.157
         250-SIZE 20480000
         250-STARTTLS
         250-AUTH PLAIN LOGIN
         250-8BITMIME
         250-PIPELINING
         250 AUTH=PLAIN LOGIN
  SMTP>> STARTTLS
  SMTP<< 220 Begin TLS negotiation now
  SMTP>> EHLO ****-**.com
  SMTP<< 250-**.***.26.157
         250-8BITMIME
         250-SIZE 20480000
         250-AUTH=PLAIN LOGIN
         250-AUTH PLAIN LOGIN
         250 PIPELINING
  SMTP>> MAIL FROM:<**@****-**.com> SIZE=1374
  SMTP>> RCPT TO:<**@****.com>
  SMTP>> DATA
  SMTP<< 550 Cannot receive from specified address <**@****-**.com>: Unauthenticated senders not allowed
  SMTP<< 503 Must have sender before recipient
  SMTP<< 503 Must have valid receiver and originator
  SMTP>> QUIT
LOG: MAIN
  ** **@****.com R=send_via_sendgrid T=sendgrid_smtp H=smtp.sendgrid.net [198.37.144.225] X=TLSv1.2:AES128-GCM-SHA256:128: SMTP error from remote mail server after MAIL FROM:<**@****-**.com> SIZE=1374: 550 Cannot receive from specified address <**@****-**.com>: Unauthenticated senders not allowed
LOG: MAIN
  cwd=/var/spool/exim 8 args: /usr/sbin/exim -v -t -oem -oi -f <> -E1ZjWjO-0006T8-Eq
LOG: MAIN
  <= <> R=1ZjWjO-0006T8-Eq U=mailnull P=local S=1383 T="Mail delivery failed: returning message to sender"
LOG: MAIN
  cwd=/var/spool/exim 4 args: /usr/sbin/exim -v -Mc 1ZjWjn-0006TR-BX
delivering 1ZjWjn-0006TR-BX
LOG: MAIN
  Completed
LOG: MAIN
  => ** <**@****-**.com> R=localuser T=local_delivery
LOG: MAIN
  Completed

Note that SMTP>> AUTH LOGIN and it's following six lines are not called...?

The question is, why is exim omitting the actual SMTP>> AUTH LOGIN part of the request, but only sometimes? It's using the same exact connection configuration (you can see it referenced in both logs as R=send_via_sendgrid T=sendgrid_smtp).

Answer 1

EDIT Nov 8, 2015:

The solution is to use

hosts_require_auth = <; $host_address
hosts_require_tls = <; $host_address

Instead of

hosts_require_auth = smtp.sendgrid.net
hosts_require_tls = smtp.sendgrid.net

The unusual-looking <; syntax is in case the hostname resolves to an IPv6 address (since from what it sounds like the colons in an IPv6 address can break things otherwise). The $host_address variable is used to solve the case where the IP address that the hostname resolves to changes (such as in this case with smtp.sendgrid.net resolving to multiple IPs and sometimes a different one being resolved to mid-process) - I think it prevents it from needing to be looked up again (see also The smtp transport). Credit Configuring Exim to use Gmail as a Smarthost and also the OP and @wurtel.

PREVIOUS ANSWER / HOW TO TEST AND REPRODUCE::

I believe @wurtel's comment on the question about the IP address changing is right on because I can reliably reproduce this by using a script to rapidly change which IP smtp.sendgrid.net resolves. I also confirmed that without any entry in the hosts file, this issue happens at least every 2 hours when I'm sending an email every 5 seconds, but when I hard-coded an IP into /etc/hosts, I went for 8 hours without any errors at that frequency of sending, so that's the temporary workaround I'm using for now.

Here's how I reproduced this issue. NOTE: this is current as the end of October 2015 - if you're trying it after that the IPs may be different so run dig smtp.sendgrid.net and use two IPs it returns instead.

Add this to /etc/hosts

108.168.190.108 smtp.sendgrid.net

Save this to a PHP file, replacing [email protected] with an email address you control.

#!/usr/local/bin/php
<?php
while (true) {
    mail('[email protected]', 'Test email deletethiswithafilter', 'test ' . time());
    usleep(500000);
}

Save this to a PHP file and run it while the above is running also. Every 5ms - 15ms it will toggle the entry in the hosts file for smtp.sendgrid.net between the two IPs that it resolves to which are 158.85.10.138 and 108.168.190.108

#!/usr/local/bin/php
<?php
while (true) {
    passthru('new_hosts_file_contents=`cat /etc/hosts | sed \'s/108.168.190.108/ip108/g\' | sed \'s/158.85.10.138/ip158/g\' | sed \'s/ip108/158.85.10.138/g\' | sed \'s/ip158/108.168.190.108/g\'`; echo "$new_hosts_file_contents" > /etc/hosts 2>&1');
    usleep(10000 + rand(-5000,5000));
}