Sendmail Read Timeouts

[dresdn]

Hello everyone.

I received a complaint today from a co-worker that she was unable to receive attachments from an outside party. After doing some investigation and looking at the bounce-backs the sender received, it seems there's a timeout problem, and I can't seem to isolate it, hence my post here. =)

Basically, I'm getting the following error in the maillog:

Code: Select all

Aug 13 04:58:35 mail sendmail[19591]: k6N1lfVk019591: SYSERR(root): collect: read timeout on connection from localhost, from=<sender@domain.com>


In looking through my logs, I've been seeing a lot of these from several different e-mail addresses.

If I had to guess, I would get a network problem, but for this one user, I have been sending e-mails back and forth without a problem and she claims the attachments are only ~20k. But, I was able to send her an attachment of 200k, which in a way rules out the network connectivity (depending on how they have their mail setup I guess).

So now I'm kind of leaning towards Sendmail, but I'm not sure. Anyone have any ideas?

I'm running Scalix 10.0.1 on RHEL 4.

Thanks in advance.

-Mike

[ScalixSupport]

Hi Mike,

Can you clear a couple of thngs up here? First, is your co-worker a Scalix user? Second, are you using SpamAssassin with the MAILFILTER=TRUE in your smtpd.cfg file? If both of those are true, can you enable the SMTP Relay log by adding:

DEBUG_LOG=TRUE

to your smtpd.cfg file and restarting the SMTP Relay by typing:

omoff -d0 -w smtpd
omon smtpd

Now, the next time you see something like this in your maillog, can you find the corresponding log entry in the /var/opt/scalix/tmp/smtpd.log file and post that data here?

Thanks,
Rachel

[dresdn]

Hi Rachel,

Can you clear a couple of thngs up here? First, is your co-worker a Scalix user?

Yes, the co-worker is a Scalix user on the same system.

Second, are you using SpamAssassin with the MAILFILTER=TRUE in your smtpd.cfg file?

I don't have a MAILFILTER=TRUE, but I do have a SMTPFILTER=TRUE. Is that the same thing?

If both of those are true, can you enable the SMTP Relay log by adding:

DEBUG_LOG=TRUE

I went ahead and did that. I'll have the outside user try and re-send the e-mail that was causing the problems and post what I find.

Thanks!

-Mike

[dresdn]

Hi Rachel,

I received a response that the original person send an e-mail with 2 attachments to myself and the original recipient. In the tmp/smtpd.log, I did see everything go through correctly and that it was accepted for delivery. What I did then was grep the maillog for the message ID, and then grep again for the new message ID after the hand-off to the milter.

Here are the results:

Code: Select all

[root@mail log]# grep 'k7FL0Bx5015309' maillog
Aug 15 14:00:11 mail sendmail[15309]: k7FL0Bx5015309: from=<person@sender.com>, size=3884, class=0, nrcpts=2, msgid=<5841E47801E22649BDE62DD16807DCE902D022C7@senderdomain.com>, proto=ESMTP, relay=root@localhost
Aug 15 14:00:14 mail sendmail[15309]: k7FL0Bx5015309: to=<mike@domain.com>,<mbundy@domain.com>, delay=00:00:03, xdelay=00:00:03, mailer=relay, pri=63884, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0, stat=Sent (k7FL0Bit015310 Message accepted for delivery)
[root@mail log]# grep 'k7FL0Bit015310' maillog
Aug 15 14:00:12 mail sendmail[15310]: k7FL0Bit015310: from=<person@sender.com>, size=4062, class=0, nrcpts=2, msgid=<5841E47801E22649BDE62DD16807DCE902D022C7@senderdomain.com>, proto=ESMTP, daemon=MTA, relay=localhost.localdomain [127.0.0.1]
Aug 15 14:00:14 mail sendmail[15310]: k7FL0Bit015310: Milter add: header: X-Virus-Scanned: amavisd-new 2.4.2 (20060627) at domain.com
Aug 15 14:00:14 mail sendmail[15310]: k7FL0Bit015310: Milter add: header: X-Spam-Score: -0.944
Aug 15 14:00:14 mail sendmail[15310]: k7FL0Bit015310: Milter add: header: X-Spam-Level:
Aug 15 14:00:14 mail sendmail[15310]: k7FL0Bit015310: Milter add: header: X-Spam-Status: No, score=-0.944 tagged_above=-9999 required=6.31\n\ttests=[AWL=-0.496, BAYES_00=-2.599, DATE_IN_PAST_03_06=0.478,\n\tHTML_40_50=0.496, HTML_MESSAGE=0.001, HTML_TITLE_EMPTY=0.214,\n\tNO_REAL_NAME=0.961, UNPARSEABLE_RELAY=0.001]
Aug 15 14:00:14 mail sendmail[15309]: k7FL0Bx5015309: to=<mike@domain.com>,<mbundy@domain.com>, delay=00:00:03, xdelay=00:00:03, mailer=relay, pri=63884, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0, stat=Sent (k7FL0Bit015310 Message accepted for delivery)
Aug 15 14:00:15 mail sendmail[15321]: k7FL0Bit015310: to=<mbundy@domain.com>,<mike@domain.com>, delay=00:00:03, xdelay=00:00:01, mailer=scalix, pri=154062, relay=mail, dsn=2.0.0, stat=Sent (Ok)


The extremely odd thing is that what you see is all I can find in reference to that e-mail. I don't see anything in my Inbox and neither does the other recipient.

Am I missing something here?

[ScalixSupport]

Hi Mike,

So, you're seeing the message come into smtpd and it's handed off to sendmail, but you're never receiving it in Scalix? Did you rebuild your sendmail.cf file from the sendmail.mc file at some point? If so, you need to run "omsendin" to re-add the Scalix specific rules, then restart sendmail.

If that's not the case, can you run:

sendmail -bt
> 3,0 mike@domain.com

and post the results?

Thanks,
Rachel

[dresdn]

So, you're seeing the message come into smtpd and it's handed off to sendmail, but you're never receiving it in Scalix?

For the latest one the sender had sent, yes. For all the other ones, I was seeing the "collect: read timeout" errors. What is happening now seems to be a secondary problem that's occuring with this domain. What's odd is that from other accounts (ie. my yahoo, gmail, etc.) I can send attachments to my Scalix account without a problem.

Did you rebuild your sendmail.cf file from the sendmail.mc file at some point? If so, you need to run "omsendin" to re-add the Scalix specific rules, then restart sendmail.

Yes I had done that, and that's been taken care of. The last time I modified the sendmail.cf was a long time ago.

sendmail -bt
> 3,0 mike@domain.com

and post the results?

Well, since it's becoming more and more of a pain, I'll just leave my domain and e-mail (even though I really don't like doing so ;)

Code: Select all

[root@mail ~]# sendmail -bt
ADDRESS TEST MODE (ruleset 3 NOT automatically invoked)
Enter <ruleset> <address>
> 3,0 mbydalek@contentconnections.com
canonify           input: mbydalek @ contentconnections . com
Canonify2          input: mbydalek < @ contentconnections . com >
Canonify2        returns: mbydalek < @ contentconnections . com . >
canonify         returns: mbydalek < @ contentconnections . com . >
parse              input: mbydalek < @ contentconnections . com . >
Parse0             input: mbydalek < @ contentconnections . com . >
Parse0           returns: mbydalek < @ contentconnections . com . >
ParseLocal         input: mbydalek < @ contentconnections . com . >
ParseLocal       returns: mbydalek < @ contentconnections . com . >
Parse1             input: mbydalek < @ contentconnections . com . >
Parse1           returns: $# scalix $@ mail $: mbydalek < @ contentconnections . com . >
parse            returns: $# scalix $@ mail $: mbydalek < @ contentconnections . com . >
>


Going back to the original posting, I've since had several more "collect: read timeout" errors from that sender, but I can't find anything in the smtpd.log with that mail ID. I did a grep of 'collect' on the maillog and the newest lines are below.

Code: Select all

Aug 15 14:46:40 mail sendmail[14254]: k7FKke3e014254: SYSERR(root): collect: read timeout on connection from localhost, from=<phansen@mun.ca>
Aug 15 14:55:34 mail sendmail[14845]: k7FKtD94014845: SYSERR(root): collect: read timeout on connection from localhost, from=<Rockhurst4@ruceci.com>
Aug 15 15:11:50 mail sendmail[16344]: k7FLBoBr016344: SYSERR(root): collect: read timeout on connection from localhost, from=<phansen@mun.ca>
Aug 15 15:15:24 mail sendmail[22273]: k7FMFO7e022273: collect: premature EOM: unexpected close
Aug 15 15:15:24 mail sendmail[22273]: k7FMFO7e022273: collect: unexpected close on connection from localhost, sender=<phansen@mun.ca>
Aug 15 15:37:31 mail sendmail[18631]: k7FLUxAY018631: SYSERR(root): collect: read timeout on connection from localhost, from=<ejgidzljni@ntli.net>
Aug 15 15:45:19 mail sendmail[24438]: k7FMijjL024438: collect: premature EOM: unexpected close
Aug 15 15:45:19 mail sendmail[24438]: k7FMijjL024438: collect: unexpected close on connection from localhost, sender=<goldiastarbuck@malaysia.net>
Aug 15 15:52:41 mail sendmail[20503]: k7FLqfmF020503: SYSERR(root): collect: read timeout on connection from localhost, from=<phansen@mun.ca>


So I do have a smtpd.log that captured these e-mails, but how do I find in the smtpd.log the corresponding transactions? I did a search for the time, ie. 14:46:40 and came up empty.

Thanks for the help.

-Mike

[ScalixSupport]

Hi Mike,

You should be able to search for:

hansen@mun.ca
Rockhurst4@ruceci.com
phansen@mun.ca

and so on. Once found, you can compare the time, to match up the messages.

Thanks,
Rachel

[dresdn]

and so on. Once found, you can compare the time, to match up the messages.

That's exactly the problem I'm having. For example, if I pick the odd e-mail of the bunch, ejgidzljni@ntli.net, and search for it, the time in the maillog was Aug 15 15:37:31. The time in the smtpd.log is 14:30:59, not even close. Plus, there is only one refence in the smtpd.log which *must* be the one in the maillog.

Here's the output from the smtpd.log for that e-mail address:

Code: Select all

Cli 9212/5 rcvd: 'EHLO bagu-cache-4.server.ntli.net'
Cli 9212/5 sent  : 250-mail.contentconnections.com Hello spc2-warr1-0-0-cust132.bagu.broadband.ntl.com [82.10.172.133], pleased to meet you
        250-AUTH PLAIN LOGIN DIGEST-MD5 CRAM-MD5 GSSAPI
        250-AUTH=LOGIN
        250-DSN
        250 8BITMIME

Cli 9212/5 rcvd: 'MAIL FROM: <ejgidzljni@ntli.net>'
Cli 9212/5 sent  : 250 ejgidzljni@ntli.net... Sender ok

Cli 9212/5 rcvd: 'RCPT TO: <abooth@contentconnections.com>'
  ... new process 18631
9212: Allocate new sendmail process 18631
Cli 9212/5 rcvd S: '220 mail.contentconnections.com ESMTP Sendmail 8.13.1/8.13.1/Submit; Tue, 15 Aug 2006 14:30:59 -0700'
Cli 9212/5 rcvd S: '250 2.1.0 <ejgidzljni@ntli.net>... Sender ok'
Cli 9212/5 sent S: rcpt to:  <abooth@contentconnections.com>

Cli 9212/5 rcvd S: '250 2.1.5 <abooth@contentconnections.com>... Recipient ok'
Cli 9212/5 sent  : 250 2.1.5 <abooth@contentconnections.com>... Recipient ok

Cli 9212/5 rcvd: 'DATA'
Cli 9212/5 sent  : 354 Enter mail, end with "." on a line by itself (relay)

Cli 9212/5 sent S: data

Cli 9212/5 rcvd S: '354 Enter mail, end with "." on a line by itself'
Cli 9212/5 sent S: Received: from bagu-cache-4.server.ntli.net (spc2-warr1-0-0-cust132.bagu.broadband.ntl.com 82.10.172.133)
            by mail.contentconnections.com (Scalix SMTP Relay 10.0.1.3)
            via ESMTP; Tue, 15 Aug 2006 14:31:36 -0700 (MST)
        From:   "" <ejgidzljni@ntli.net>
        To: abooth@contentconnections.com
        Subject:
        Date:   Tue, 15 Aug 2006 23:41:24 -0200
        MIME-Version: 1.0
        Content-Type: multipart/related;
                boundary="----=_NextPart_000_0002_01C6C0C4.52135700"
        X-Mailer: Microsoft Office Outlook, Build 11.0.5510
        Thread-Index: AcbAxFITAq6Tcid7T/iq7B8kxSDJHg==
        X-MimeOLE: Produced By Microsoft MimeOLE V6.00.2900.2869
        Message-Id: <92EE73BFB6B5A32.A07324E357@ntli.net>

        ------=_NextPart_000_0002_01C6C0C4.52135700
        Content-Type: multipart/alternative;
                boundary="----=_NextPart_001_0003_01C6C0C4.52135700"


        ------=_NextPart_001_0003_01C6C0C4.52135700
        Content-Type: text/plain;
                charset="us-ascii"
        Content-Transfer-Encoding: 7bit


<Lots of blank lines, exactly 69 of them>

        ------=_NextPart_001_0003_01C6C0C4.52135700
        Content-Type: text/html;
                charset="us-ascii"
        Content-Transfer-Encoding: quoted-printable


Cli 9212/5 sent S: <html xmlns:v=3D"urn:schemas-microsoft-com:vml" =
        xmlns:o=3D"urn:schemas-microsoft-com:office:office" =
        xmlns:w=3D"urn:schemas-microsoft-com:office:word" =
        xmlns:st1=3D"urn:schemas-microsoft-com:office:smarttags" =
        xmlns=3D"http://www.w3.org/TR/REC-html40">

        <head>
        <META HTTP-EQUIV=3D"Content-Type" CONTENT=3D"text/html; =
        charset=3Dus-ascii">

Accepted client 9 from  (218-35-17-136.cm.dynamic.apol.com.tw)
Cli 9212/9 sent  : 220 mail.contentconnections.com ESMTP Scalix SMTP Relay 10.0.1.3; Tue, 15 Aug 2006 14:32:05 -0700 (MST)


I'm seeing the time desparity for all of the messages I'm looking for in the smtpd.log and the maillog.

For the e-mail address Rockhurst4@ruceci.com at 14:55:34, there are 2 e-mails in the smtpd.log, here are the first two lines of each transaction.

Code: Select all

Cli 9212/4 sent  : 220 mail.contentconnections.com ESMTP Scalix SMTP Relay 10.0.1.3; Tue, 15 Aug 2006 13:55:13 -0700 (MST)

Cli 9212/3 sent  : 220 mail.contentconnections.com ESMTP Scalix SMTP Relay 10.0.1.3; Tue, 15 Aug 2006 16:17:16 -0700 (MST)


So I'm wondering if the errors are not from the external side, but from the internal? Just grabbing at straws here ;)

Thanks,
Mike

[ScalixSupport]

Hi Mike,

The times not matching is very strange. I can see in your smtpd.log file that indeed the sendmail connection was made:

Code: Select all

220 mail.contentconnections.com ESMTP Sendmail 8.13.1/8.13.1/Submit; Tue, 15 Aug 2006 14:30:59 -0700


and in the received from header of that message:

Code: Select all

Received: from bagu-cache-4.server.ntli.net (spc2-warr1-0-0-cust132.bagu.broadband.ntl.com 82.10.172.133)
            by mail.contentconnections.com (Scalix SMTP Relay 10.0.1.3)
            via ESMTP; Tue, 15 Aug 2006 14:31:36 -0700 (MST)


it shows the time when the header was written. There does seem to be a bit of a latency there (~37 seconds), but let's not get defocused on that for now.

So, there should be a corresponding entry in the maillog file that shows that connection at 14:30:59.

A couple of things you can do. First, you might want to temporarily disable your amavis milter in sendmail just to see if that's introducing some type of problem. Second, you can enable extended sendmail logging by adding something like:

Code: Select all

-X /var/log/extended.log

to your /etc/sysconfig/sendmail file, then restarting sendmail. That way you can see the entire message as it's received from sendmail, including subject lines and message ID's which will make it easier to match up what's being received by the SMTP Relay and sendmail.

Thanks,
Rachel