Re: Delayed email because of signing

From: Jason Clint <jtclint_at_gmail.com>
Date: Wed, 8 Dec 2010 16:31:48 -0700

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?

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]
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\t
0|X-Priority:=203|X-Library:=20Indy=209.00.10;\n\tb=lnsr6SvkY7ER/rk//UB9VQN92yQdEzmIhv6qbQXGStFTzc0sAu2Z9J4/YShAI1HFq\n\t
xiMvhyprHCa1nujQ7KEut0TUy65ND/uKsIzsiSnUhrgsb7+TfZrLHfadd9BLckT5ut\n\t
4hFwTRlx9F44mCTt2MzJ8hD186gtzcvBuiChRxzA=
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)
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]
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\t
0|X-Priority:=203|X-Library:=20Indy=209.00.10;\n\tb=A3IQUQOP5q2A7KCz+TmZ3t6vFQtfxBrICDxb8hyr1UvYm5xeL+93X7cNPhA1cHqGu\n\t
WNp0QrPTR2ILmUR0tf7IwGjrL8NVwvAykHiw5tentfExFdmlQV0FDEK6V+3MdpaZs4\n\t
H6zUeYpE59hGkktfIbVlIHl5157HOFKKv9ofdNFU=
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)


On Wed, Dec 8, 2010 at 4:13 PM, Murray S. Kucherawy <msk_at_cloudmark.com>wrote:

> The first log stamp there is at 16:08:26 and the last is at 16:08:27.
> The first is sendmail identifying the sender portion of the envelope, at
> which point message processing started. The next is sendmail indicating
> that it had added a DKIM signature header field to the message (at the
> instruction of opendkim). The third and final one, one second later, is the
> completion of relaying of that message to some other host.
>
>
>
> That all took, at most, just under two seconds.
>
>
> Do you have an example of one that took five seconds or more?
>
>
>
> *From:* Jason Clint [mailto:jtclint_at_gmail.com]
> *Sent:* Wednesday, December 08, 2010 3:11 PM
> *To:* Murray S. Kucherawy
>
> *Subject:* Re: Delayed email because of signing
>
>
>
> there is a strip from the logs for one email as well, from the second setup
> which takes 5 seconds for 1 email.
>
> On Wed, Dec 8, 2010 at 4:10 PM, Jason Clint <jtclint_at_gmail.com> wrote:
>
> Dec 8 16:08:26 mail8 sendmail[4440]: oB8N8QhI004440: from=<
> myuser_at_mydomain.com>, size=216, class=0, nrcpts=1, msgid=<
> 201012082308.oB8N8QhI004440_at_mail8.mydomain.com>, proto=ESMTP, daemon=MTA,
> relay=mycomputer.myotherdomain.com [10.0.88.97]
> Dec 8 16:08:26 mail8 sendmail[4440]: oB8N8QhI004440: Milter insert (1):
> header: DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=
> mydomain.com;\n\ts=mail8;
> t=1291849706;\n\tbh=QSgPvOwUjJTwPVjpDpfasfDfFSVT7pP97txaRIs5rX4=;\n\th=From:Subject:To:Date;\n\tb=Rxapyu/o1RKzV/mLNfLaA6HdfjPpet03EdeFlehEsm2V/IXX5TfXE2rzlLLqaIFyq\n\t
> 6nunQHuiibzdV3R3CEmw2Wz2cjdCXC/3+UMrlxMUrpeOV0Nx5PxTdQ8dxNZSLiD0Fs\n\t
> 2OP2PvSRWD1ugP9jX6aa/0VISH2zAGU8Tdb0U+xA=
> Dec 8 16:08:27 mail8 sendmail[4443]: oB8N8QhI004440: to=<
> jclint_at_myotherdomain.com>, delay=00:00:01, xdelay=00:00:00, mailer=esmtp,
> pri=120216, relay=exchange.myotherdomain.com. [10.0.1.21], dsn=2.0.0,
> stat=Sent ( <201012082308.oB8N8QhI004440_at_mail8.mydomain.com> Queued mail
> for delivery)
>
>
>
> On Wed, Dec 8, 2010 at 4:03 PM, Murray S. Kucherawy <msk_at_cloudmark.com>
> wrote:
>
> This is why I would like to see logs from the “second setup” server showing
> a single message taking a long time to go through. To do this, pick a queue
> ID from the log for a message that took a while, “grep” for it in the log,
> and just paste the output of your “grep” here. Then we can see if opendkim
> is causing the delay or something else.
>
>
>
> *From:* opendkim-users-bounce_at_lists.opendkim.org [mailto:
> opendkim-users-bounce_at_lists.opendkim.org] *On Behalf Of *Jason Clint
> *Sent:* Wednesday, December 08, 2010 2:55 PM
> *To:* Murray S. Kucherawy
> *Cc:* Alessandro Vesely; opendkim-users_at_lists.opendkim.org
>
>
> *Subject:* Re: Delayed email because of signing
>
>
>
> Well if it wasn't DNS then the only other thing I can think of would be
> that the flux of emails going into the sender directly compared the current
> setup which is being relayed caused it to slow down. Otherwise what else
> would it be, I mean looking at the 3 setups
>
>
>
> First setup: No DKIM no Relay 1-2 emails a second
> Second Setup: DKIM no Relay 1 email every 5 seconds
> Current Setup: DKIM with Relay 1-2 emails a second
>
> On Wed, Dec 8, 2010 at 3:30 PM, Murray S. Kucherawy <msk_at_blackops.org>
> wrote:
>
> On Wed, 8 Dec 2010, Jason Clint wrote:
>
> Sorry I take part of that back, the overall send was actually faster. Even
> the dkim signing, possibly like Todd said it was related to dns, which would
> explain why the windows machine with the app did not work as well as the
> linux sendmail box without dkim which just relayed.
>
>
>
> DKIM signing is unrelated to DNS. Only verifying involves DNS queries.
>
>
>
>
>
>
>
Received on Wed Dec 08 2010 - 23:32:05 PST