Re: Delayed email because of signing

From: Murray S. Kucherawy <msk_at_blackops.org>
Date: Wed, 8 Dec 2010 18:43:22 -0800 (PST)

On Wed, 8 Dec 2010, Jason Clint wrote:
> I had to pull this from another server with the same setup since the one I
> was getting the info from was way to busy to get a clear log.  I sent 2
> emails in a row and you can see where the time delay is, its not the emails
> themselves its after the email is done sending in the log that it delays. 
> The reason for this that I have found is because the sender app waits for
> verfication that the email got sent out before proceeding.  I am still
> trying to figure out what exactly it is waiting for, the difference from the
> setup before (the first setup) and the setup with dkim and no relay was
> obviously DKIM itself and the 5 second delay.  Not sure why DKIM would cause
> the response from the server to be delayed?

I don't think DKIM is doing this. It's more likely an MTA configuration
option or a local DNS issue unrelated to DKIM. Your logs tell the story:

> Dec  8 16:22:50 mail2 sendmail[3663]: oB8NMnx3003663:
> from=<myuser_at_mydomain.com>, size=224, class=0, nrcpts=1,
> msgid=<201012082322.oB8NMnx3003663_at_mail2.mydomain.com>, proto=ESMTP,
> daemon=MTA, relay=mycomputer.myotherdomain.com [10.0.88.97]

This is the start of job oB8NMnx3003663, time 16:22:50.

> Dec  8 16:22:50 mail2 sendmail[3663]: oB8NMnx3003663: Milter insert (1):
> header: DKIM-Signature:  v=1; a=rsa-sha256;
> c=relaxed/simple;\n\td=mydomain.com; s=mail2;t=1291850570;\n\tbh=QSgPvOwUjJTwPVjpDpfasfDfFSVT7pP97txaRIs5rX4=;\n\th=From
> :Subject:To:Date;\n\tz=X-WIRE-Project:=2039000001|From:=20"Company=20Name"=
> 20<myus\n\t er_at_mydomain.com>|Subject:=20Email=20Checking|To:=20jcli\n\t
> nt_at_myotherdomain.com|Date:=20Wed,=208=20Dec=202010=2016:22:51=20-070\n\t0|X-Priority:=203|X-Library:=20Indy=209.00.10;\n\tb=lnsr6SvkY7ER/rk//UB9VQN
> 92yQdEzmIhv6qbQXGStFTzc0sAu2Z9J4/YShAI1HFq\n\t
> xiMvhyprHCa1nujQ7KEut0TUy65ND/uKsIzsiSnUhrgsb7+TfZrLHfadd9BLckT5ut\n\t
> 4hFwTRlx9F44mCTt2MzJ8hD186gtzcvBuiChRxzA=

The MTA was instructed to add that signature within the same second.

> Dec  8 16:22:50 mail2 sendmail[3666]: oB8NMnx3003663:
> to=<jclint_at_myotherdomain.com>, delay=00:00:00, xdelay=00:00:00,
> mailer=esmtp, pri=120224, relay=exchange.myotherdomain.com. [10.0.1.21],
> dsn=2.0.0, stat=Sent ( <201012082322.oB8NMnx3003663_at_mail2.mydomain.com>
> Queued mail for delivery)

The job relayed successfully to exchange.myotherdomain.com within the same
second. The job is done. Total time for this job was less than one
second. At this point your application should have been told by sendmail
that this job is complete and it's ready for more work.

There's no guarantee of fast handling by exchange.myotherdomain.com, so
perhaps the delay you're seeing in delivery is actually there. But there
was no noticeable delay here.

> Dec  8 16:22:55 mail2 sendmail[3667]: oB8NMtkD003667:
> from=<myuser_at_mydomain.com>, size=224, class=0, nrcpts=1,
> msgid=<201012082322.oB8NMtkD003667_at_mail2.mydomain.com>, proto=ESMTP,
> daemon=MTA, relay=mycomputer.myotherdomain.com [10.0.88.97]

This is the start of job oB8NMtkD003667, time 16:22:55. Note that this is
not the same job as before; that one finished, and this is a new one.
Compare the job IDs:

         oB8NMnx3003663
         oB8NMtkD003667

There was a five-second delay between the end of the first job and the
start of the second, but not a five-second delay within either of the two
jobs that can be attributed to DNS or any filters, etc.

> Dec  8 16:22:55 mail2 sendmail[3667]: oB8NMtkD003667: Milter insert (1):
> header: DKIM-Signature:  v=1; a=rsa-sha256;
> c=relaxed/simple;\n\td=mydomain.com; s=mail2;t=1291850575;\n\tbh=QSgPvOwUjJTwPVjpDpfasfDfFSVT7pP97txaRIs5rX4=;\n\th=From
> :Subject:To:Date;\n\tz=X-WIRE-Project:=2039000001|From:=20"Company=20Name"=
> 20<myus\n\t er_at_mydomain.com>|Subject:=20Email=20Checking|To:=20jcli\n\t
> nt_at_myotherdomain.com|Date:=20Wed,=208=20Dec=202010=2016:22:56=20-070\n\t0|X-Priority:=203|X-Library:=20Indy=209.00.10;\n\tb=A3IQUQOP5q2A7KCz+TmZ3t6
> vFQtfxBrICDxb8hyr1UvYm5xeL+93X7cNPhA1cHqGu\n\t
> WNp0QrPTR2ILmUR0tf7IwGjrL8NVwvAykHiw5tentfExFdmlQV0FDEK6V+3MdpaZs4\n\t
> H6zUeYpE59hGkktfIbVlIHl5157HOFKKv9ofdNFU=

Signature insertion within the same second.

> Dec  8 16:22:56 mail2 sendmail[3670]: oB8NMtkD003667:
> to=<jclint_at_myotherdomain.com>, delay=00:00:01, xdelay=00:00:00,
> mailer=esmtp, pri=120224, relay=exchange.myotherdomain.com. [10.0.1.21],
> dsn=2.0.0, stat=Sent ( <201012082322.oB8NMtkD003667_at_mail2.mydomain.com>
> Queued mail for delivery)

Transport complete in the next second. Total time for this job is less
than two seconds. sendmail and syslogd concur because both of their
timestamps say the same thing (16:22:56 from syslog, one second after the
other one; and "delay=00:00:01" from sendmail).

There's nothing in the logs that would explain the interval between the
end of the first job and the start of the second other than your
application taking that long to initiate the second job. On completion
of the first job, if your application remains connected to sendmail, it
can just go right into the next transaction.

The only other thing I can think of is that on connection to sendmail it
tries to do a reverse DNS lookup on the connecting IP address, and that
needs to complete (or time out). This could be the source of your delay
if your internal DNS isn't set up right or sendmail's having problems
talking to a nameserver. One way to test this is to log in to your
sendmail box and type:

         host 10.0.88.97

...and see how long it takes to get an answer, and then when you get that
answer, repeat the lookup for the hostname it returned (if any). If the
replies aren't nearly instant, you may have found your problem.

-MSK
Received on Thu Dec 09 2010 - 02:43:49 PST