On Mon, May 16, 2011 at 12:21:51PM -0700, Murray S. Kucherawy wrote:
> >
> > From: opendkim-dev-bounce_at_lists.opendkim.org [mailto:opendkim-dev-bounce_at_lists.opendkim.org] On Behalf Of Gary Mills
> >
> > I could check on how frequently this timeout occurs; it it's
> > infrequent, it's not a problem.
I found 5625 of them in today's syslog so far. That seems high to me.
> The interesting thing to me is the previous report you gave about
> the seemingly random distribution of timeouts you see, when the
> configured timeout is five seconds.
I looked at some now; they all appear to be 60 seconds now. I don't
know why they were random before. Here are the sendmail messages
for four timeouts that occurred around the same time:
May 16 19:53:36 electra sm-mta[26559]: [ID 801593 mail.info] p4H0rZj8026559: from=<XXXX_at_richtig-wichtig.org>, size=2087, class=0, nrcpts=1, msgid=<000001cc06b89344a3c0e5187fc8_at_20012724229.cab.prima.net.ar>, proto=ESMTP, daemon=MTA, relay=200-127-24-229.cab.prima.net.ar [200.127.24.229] (may be forged)
May 16 19:53:37 electra sm-mta[26570]: [ID 801593 mail.info] p4H0rbs5026570: from=<YYYY_at_ualberta.ca>, size=3860, class=0, nrcpts=1, msgid=<f06240802c9f7763ab724@[129.128.54.128]>, proto=ESMTP, daemon=MTA, relay=smtp.srv.ualberta.ca [129.128.5.19]
May 16 19:53:38 electra sm-mta[26574]: [ID 801593 mail.info] p4H0rcZE026574: from=<prvs=01189a0777=ZZZZ_at_international.gc.ca>, size=3513, class=0, nrcpts=1, msgid=<60455759277F0F4684955A10D1EE76560A50F9EF_at_manildmres01.d.r.dfait-maeci.gc.ca>, proto=ESMTP, daemon=MTA, relay=mail6.international.gc.ca [198.103.104.107]
May 16 19:53:39 electra sm-mta[26573]: [ID 801593 mail.info] p4H0rclo026573: from=<AAAA_at_yahoo.co.uk>, size=16904, class=0, nrcpts=1, msgid=<20110517125206.21500.qmail_at_user-7b2b6ee627>, proto=SMTP, daemon=MTA, relay=[187.5.238.232]
May 16 19:54:36 electra sm-mta[26559]: [ID 801593 mail.error] p4H0rZj8026559: Milter (dkim): timeout before data read, where=eom
May 16 19:54:36 electra sm-mta[26559]: [ID 801593 mail.info] p4H0rZj8026559: Milter (dkim): to error state
May 16 19:54:37 electra sm-mta[26559]: [ID 801593 mail.info] p4H0rZj8026559: Milter: data, reject=550 5.7.1 id p4H0rZj8026559 from 200.127.24.229 rejected. See
http://www.spamhaus.org/zen/
May 16 19:54:37 electra sm-mta[26559]: [ID 801593 mail.info] p4H0rZj8026559: to=<BBBB_at_cc.umanitoba.ca>, delay=00:01:01, pri=32087, stat=id p4H0rZj8026559 from 200.127.24.229 rejected. See
http://www.spamhaus.org/zen/
May 16 19:54:37 electra sm-mta[26570]: [ID 801593 mail.error] p4H0rbs5026570: Milter (dkim): timeout before data read, where=eom
May 16 19:54:37 electra sm-mta[26570]: [ID 801593 mail.info] p4H0rbs5026570: Milter (dkim): to error state
May 16 19:54:37 electra sm-mta[26570]: [ID 801593 mail.info] p4H0rbs5026570: Milter: data, reject=452 4.2.1 id p4H0rbs5026570 from 129.128.5.19 temporary embargo. See
http://mail.cc.umanitoba.ca/grey/
May 16 19:54:37 electra sm-mta[26570]: [ID 801593 mail.info] p4H0rbs5026570: to=<CCCC_at_cc.umanitoba.ca>, delay=00:01:00, pri=33860, stat=id p4H0rbs5026570 from 129.128.5.19 temporary embargo. See
http://mail.cc.umanitoba.ca/grey/
May 16 19:54:38 electra sm-mta[26574]: [ID 801593 mail.error] p4H0rcZE026574: Milter (dkim): timeout before data read, where=eom
May 16 19:54:38 electra sm-mta[26574]: [ID 801593 mail.info] p4H0rcZE026574: Milter (dkim): to error state
May 16 19:54:38 electra sm-mta[26574]: [ID 801593 mail.info] p4H0rcZE026574: Milter add: header: X-DCC-UofM-Metrics: electra 1033; Body=1 Fuz1=1 Fuz2=1
May 16 19:54:38 electra sm-mta[26839]: [ID 801593 mail.info] p4H0rcZE026574: to=<DDDD_at_cc.umanitoba.ca>, delay=00:01:00, xdelay=00:00:00, mailer=local, pri=33794, relay=localhost, dsn=2.0.0, stat=Sent
May 16 19:54:39 electra sm-mta[26573]: [ID 801593 mail.error] p4H0rclo026573: Milter (dkim): timeout before data read, where=eom
May 16 19:54:39 electra sm-mta[26573]: [ID 801593 mail.info] p4H0rclo026573: Milter (dkim): to error state
May 16 19:54:39 electra sm-mta[26573]: [ID 801593 mail.info] p4H0rclo026573: Milter: data, reject=550 5.7.1 id p4H0rclo026573 from 187.5.238.232 rejected. See
http://www.spamhaus.org/zen/
May 16 19:54:39 electra sm-mta[26573]: [ID 801593 mail.info] p4H0rclo026573: to=<EEEE_at_umanitoba.ca>, delay=00:01:01, pri=46904, stat=id p4H0rclo026573 from 187.5.238.232 rejected. See
http://www.spamhaus.org/zen/
I see something interesting: the timeouts appear in clusters. There were
107 of them around 16:32 and 20 around 19:54. Earlier, there were 144 of
them around 04:15. I don't suppose that a timeout in one thread affects
other threads. Some temporary network problem seems most likely to me.
I'll investigate further.
Here's how it looks for the afternoon, showing count at each time time:
26 13:10
90 13:11
177 13:12
222 13:13
52 13:14
1 13:15
88 13:27
55 13:28
134 13:29
5 13:55
57 14:34
172 14:35
146 14:36
155 14:37
75 14:38
81 16:30
37 16:31
107 16:32
20 19:54
--
-Gary Mills- -Unix Group- -Computer and Network Services-
Received on Tue May 17 2011 - 02:38:17 PST