Scalix server receiving email performance

[vorlon2261]

Hi guys,

Upgraded to 10.0.0 recently, and since its happened, Scalix takes its sweet time
to receive emails, some taking as much as 3 hours to arrive when they used to
take moments.

We have a postfix server on a firewall which forwards emails in to the Scalix server
behind our firewall, and its complaining of network timeouts, when nothing else is.
Sending emails out via the Scalix server is unaffected, internal emails are unaffected,
other services involving both the server Scalix lives on and the firewall are unaffected.

Has anyone seen something similar? What can I do to debug this situation further?

thanks,

Greg

[ScalixSupport]

Do you have any internet headers for a delayed message ?

Cheers

Dave

[vorlon2261]

This one is only delayed by an hour... Others have delayed longer... Email
addresses changed to protect the innocent... ;-) If I see anything different in
other emails I'll email them to you via the support email address...

Question: Is 10.0.0.175 mentioned in the Scalix SMTP relay meant to be
an IP address or is that the Scalix version?

Code: Select all

Received: from mail.unico.com.au (jumpgate.unico.com.au 10.10.1.2)
    by akiko.unico.com.au (Scalix SMTP Relay 10.0.0.175)
    via ESMTP; Tue, 21 Mar 2006 13:46:48 +1100 (EST)
Received: from mailbo.vtcif.telstra.com.au (mailbo.vtcif.telstra.com.au [202.12.144.19])
   by mail.unico.com.au (Postfix) with ESMTP id 30FD824302
   for <Spam.Someone@to.domain.com>; Tue, 21 Mar 2006 12:49:55 +1100 (EST)
Received: from mailai.vtcif.telstra.com.au (mailai.vtcif.telstra.com.au [202.12.142.17])
   by mailbo.vtcif.telstra.com.au (Postfix) with ESMTP
   id 0912A22D01; Tue, 21 Mar 2006 12:49:44 +1100 (EST)
Received: from mail2.cdn.telstra.com.au (localhost [127.0.0.1])
   by mailai.vtcif.telstra.com.au (Postfix) with ESMTP
   id 195831DA84; Tue, 21 Mar 2006 12:49:44 +1100 (EST)
Received: from wsmsg2952.srv.dir.telstra.com (wsmsg2952.srv.dir.telstra.com [192.74.195.51])
   by mail2.cdn.telstra.com.au (Postfix) with ESMTP
   id B1B8F41F4E; Tue, 21 Mar 2006 12:49:43 +1100 (EST)
Content-class: urn:content-classes:message
Subject: RE: [Case ID: 11037616] Re: Act#1-13846316-Esc#1-11356767    Case:10728552 Task:21499295 Updated at 26-Jan 15:5 [...]
Date: Tue, 21 Mar 2006 12:49:36 +1100
MIME-Version: 1.0
Content-Type: text/plain;
   charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable
Message-ID: <B15779BF86D9A7439FF960A84650624101755640@WSMSG2151V.srv.dir.telstra.com>
X-MimeOLE: Produced By Microsoft Exchange V6.5
X-MS-Has-Attach:
X-MS-TNEF-Correlator:
Thread-Topic: [Case ID: 11037616] Re: Act#1-13846316-Esc#1-11356767    Case:10728552 Task:21499295 Updated at 26-Jan 15:5 [...]
Thread-Index: AcY7TfAqg7HyXUt0R8GwqpbBR3PjsgRO1s2w
From: "From Person" <From.Person@from.domain.com>
To: <spam@sun.com>
Cc: "To Person" <To.Person@to.domain.com>


[ScalixSupport]

Code: Select all

Received: from mail.unico.com.au (jumpgate.unico.com.au 10.10.1.2)
    by akiko.unico.com.au (Scalix SMTP Relay 10.0.0.175)
    via ESMTP; Tue, 21 Mar 2006 13:46:48 +1100 (EST)
Received: from mailbo.vtcif.telstra.com.au (mailbo.vtcif.telstra.com.au [202.12.144.19])
   by mail.unico.com.au (Postfix) with ESMTP id 30FD824302
   for <Spam.Someone@to.domain.com>; Tue, 21 Mar 2006 12:49:55 +1100 (EST)

This is the important section.

It looks like mail.unico.com.au is holding on to the message for 1 hour. Is there anything in the postfix logs that show a mail deferral when talking to akiko.unico.com.au ?

Cheers

Dave

[vorlon2261]

Only thing I've found is this when running mailq:

Code: Select all

7E31E24294     6177 Tue Mar 21 10:06:31  1isto@mail.com
(conversation with 10.10.1.5[10.10.1.5] timed out while sending end of data -- message may be sent more than once)
                                         username@unico.com.au

Its an ethernet connection between the 2 and I have replaced all of the hardware in between, so I'm confident its not a hardware issue. Especially since other services that also go through this hardware aren't affected... (IP address 10.10.1.5 is the Scalix server in the above example)

[ScalixSupport]

Can you check your fatal file under /var/opt/scalix/logs to see if anything is logged there ?

Cheers

Dave

[vorlon2261]

Dave,

Have mailed fatal file to you. Theres a couple of stack traces in there, but there isn't much to go on...

Greg

[vorlon2261]

Dave,

Have been unable to figure out what Scalix is doing wrong here.

Can you suggest a strategy for falling back to 9.4.2, as it is causing unacceptable delays in email arrival.

thanks!

[ScalixSupport]

I haven't been able to look at the fatal file until today as I've been out of the office.

Be advised that there is no fallback to 9.4 after upgrading to 10.

In the fatal log I can see only one reference to a problem.

Code: Select all

SERIOUS ERROR                  Internet Mail (Incoming      ) 03.01.06 14:13:11
[OM.UX 1401] Cannot read message data.
Pid of logging process: 6773

This usually means that the sending side terminated the conversation early.

The first thing to try is to enable SMTP Logging by adding

Code: Select all

DEBUG_LOG=TRUE

to smtpd.cfg and restarting the SMTP Relay.

This will log to /var/opt/scalix/tmp/smtpd.log and will contain the complete SMTP conversation between the SMTP Relay and any sending MTA/client. Beware that this can get large if there's a lot of traffic.

This will help identify if there is a problem on the sending side.

Cheers

Dave

[vorlon2261]

Dave,

Thanks for the follow up. I've enabled debug as requested... Its giving the following:

Code: Select all

Cli 3320/3 rcvd U: 'Cannot read message data.'
Cli 3320/3: Submitted message ': <150401c64ee0$56bfa2c9$1d084743@o2.pl>' to unix.in.
        response: 'Cannot read message data.'
Cli 3320/3 Finished submitting msg  : <150401c64ee0$56bfa2c9$1d084743@o2.pl>
Cli 3320/3 sent  : Cannot read message data.

This is after getting the full message including the final '.'.

If you want, I can send through a sample or two through to the support list...

[ScalixSupport]

Can you post more of the SMTP conversation ?

Cheers

Dave

[vorlon2261]

Here 'tis:

Looks like this one figures the end of the email before the actual email ends... See below...

Code: Select all

Accepted client 3 from  (jumpgate.unico.com.au)
Cli 3320/3 sent  : 220 akiko.unico.com.au ESMTP Scalix SMTP Relay 10.0.0.175; Tue, 28 Mar 2006 13:57:35 +1100 (EST)
       
Cli 3320/3 rcvd: 'EHLO mail.unico.com.au'
Cli 3320/3 sent  : 250-akiko.unico.com.au Hello jumpgate.unico.com.au [10.10.1.2], pleased to meet you
        250-AUTH CRAM-MD5 DIGEST-MD5 LOGIN PLAIN GSSAPI
        250-AUTH=LOGIN
        250-DSN
        250 8BITMIME
       
Cli 3320/3 rcvd: 'MAIL FROM:<agent@o2.pl>'
Cli 3320/3 sent  : 250 agent@o2.pl... Sender ok
       
Cli 3320/3 rcvd: 'RCPT TO:<kalo@unico.com.au>'

Cli 3320/3 rcvd U: '220 Scalix ESMTP Ready.'
Cli 3320/3 rcvd U: '250 Ok'
Cli 3320/3 sent U: rcpt to: <kalo@unico.com.au>
       
Cli 3320/3 rcvd U: '250 Ok'
Cli 3320/3 sent  : 250 Ok
       
Cli 3320/3 rcvd: 'DATA'
Cli 3320/3 sent  : 354 Enter mail, end with "." on a line by itself (relay)
       
Cli 3320/3 sent U: data
       
Cli 3320/3 rcvd U: '354 Enter mail, end with "." on a line by itself.'

Cli 3320/3 sent U: Received: from mail.unico.com.au (jumpgate.unico.com.au 10.10.1.2)
            by akiko.unico.com.au (Scalix SMTP Relay 10.0.0.175)
            via ESMTP; Tue, 28 Mar 2006 13:57:36 +1100 (EST)
        Received: from 59.24.0.170 (unknown [59.24.0.170])
                by mail.unico.com.au (Postfix) with SMTP id DCF6224393
                for <XXXX@unico.com.au>; Sat, 25 Mar 2006 04:12:47 +1100 (EST)
        Message-ID: <150401c64ee0$56bfa2c9$1d084743@o2.pl>
        From: abc@uol.com.br <agent@o2.pl>
        To: XXXX@unico.com.au
        Subject: =?windows-1251?B?0eDs7vHy7v/y5ev87e7lIO/w7uLl5OXt6OUg7ODw6uXy6O3j7uL79SDo8fHr5eTu?=
                =?windows-1251?B?4uDt6Ok=?=
        Date: Fri, 24 Mar 2006 04:13:07 +0300
        MIME-Version: 1.0
        Content-Type: multipart/alternative;
            boundary="----=_NextPart_000_0000_DCFC24E2.B70B1675"
        X-Priority: 3
        X-MSMail-Priority: Normal
        X-Mailer: Microsoft Outlook Express V6.00.2900.2180
        X-MimeOLE: Produced By Microsoft MimeOLE V6.00.2900.2180
       
        This is a multi-part message in MIME format.
       
        ------=_NextPart_000_0000_DCFC24E2.B70B1675
        Content-Type: text/plain;
            charset="windows-1251"
        Content-Transfer-Encoding: 8bit

    SPAM SPAM SPAM SPAM


Cli 3320/3 sent U:  =C3=E8=EB=FC=E4=E8=E8 =EC=E0=F0=EA=E5=F2=EE=EB=EE=E3=EE=E2 =
        =D0=EE=F1=F1=E8=E8, =E8=EC=E5=E5=F2 =F1=F2=E5=EF=E5=ED=FC =CC=C2=C0. =
        =CE=EF=FB=F2=ED=FB=E9 =F1=EF=E5=F6=E8=E0=EB=E8=F1=F2 =E2 =
        =EE=F0=E3=E0=ED=E8=E7=E0=F6=E8=E8 =
        =EC=E0=F0=EA=E5=F2=E8=ED=E3=EE=E2=EE=E9 =
        =E4=E5=FF=F2=E5=EB=FC=ED=EE=F1=F2=E8, =F2=E5=F5=ED=EE=EB=EE=E3=E8=FF=F5 =
        =F1=EE=E7=E4=E0=ED=E8=FF =EC=E0=F0=EA=E5=F2=E8=ED=E3=EE=E2=FB=F5 =
        =EF=EE=E4=F0=E0=E7=E4=E5=EB=E5=ED=E8=E9 &laquo;=F1 =ED=F3=EB=FF&raquo;, =
        =EF=F0=EE=E2=E5=E4=E5=ED=E8=E8 =EC=E0=F0=EA=E5=F2=E8=ED=E3=EE=E2=FB=F5 =
        =E8=F1=F1=EB=E5=E4=EE=E2=E0=ED=E8=E9 =EB=FE=E1=EE=E9 =
        =F1=EB=EE=E6=ED=EE=F1=F2=E8, =EF=EB=E0=ED=E8=F0=EE=E2=E0=ED=E8=E8 =
        =F0=E5=EA=EB=E0=EC=ED=EE=E9 =E4=E5=FF=F2=E5=EB=FC=ED=EE=F1=F2=E8. =
        =D0=E5=E0=EB=E8=E7=EE=E2=E0=EB =E1=EE=EB=E5=E5 50 =
        =EF=F0=EE=E5=EA=F2=EE=E2 =E2 =EE=E1=EB=E0=F1=F2=E8 =
        =EC=E0=F0=EA=E5=F2=E8=ED=E3=E0, =E1=F0=E5=ED=E4=E8=ED=E3=E0 =E8 =
        =F0=E5=EA=EB=E0=EC=FB, =EE=F0=E3=E0=ED=E8=E7=E0=F6=E8=E8 =
       
Cli 3320/3 got .
Cli 3320/3 sent U: =EC=E0=F0=EA=E5=F2=E8=ED=E3=EE=E2=EE=E9 =F1=EB=F3=E6=E1=FB =E8 =
        =F0=E0=E7=F0=E0=E1=EE=F2=EA=E5 =EA=EE=ED=F6=E5=EF=F6=E8=E8 =
        =EC=E0=F0=EA=E5=F2=E8=ED=E3=E0. =C1=EE=EB=E5=E5 500 =
        =E2=FB=EF=F3=F1=EA=ED=E8=EA=EE=E2 =F8=EA=EE=EB=FB =
        =F0=E0=E1=EE=F2=E0=FE=F2 =ED=E0 =F0=F3=EA=EE=E2=EE=E4=FF=F9=E8=F5 =
        =E4=EE=EB=E6=ED=EE=F1=F2=FF=F5 =EA=E0=EA =E2 =
        =F0=EE=F1=F1=E8=E9=F1=EA=E8=F5, =F2=E0=EA =E8 =E2 =
        =E7=E0=F0=F3=E1=E5=E6=ED=FB=F5 =EA=EE=EC=EF=E0=ED=E8=FF=F5. =
        </font></div>
        <div align=3D"center"><strong><font =
        face=3D"Arial">&nbsp;</font></strong></div>
        <div align=3D"center"><font face=3D"Arial"><font =
        size=3D"4"><strong>=C7=E2=EE=ED=E8=F2=E5: </strong><strong>8 926 =
        2=C72-25-9=D7</strong></font></font></div>
        </font>
        </BODY>
        </HTML>
       
       
        ------=_NextPart_000_0000_DCFC24E2.B70B1675--
       
        {NULL}
        .

Cli 3320/3 rcvd U: 'Cannot read message data.'
Cli 3320/3: Submitted message ': <150401c64ee0$56bfa2c9$1d084743@o2.pl>' to unix.in.
        response: 'Cannot read message data.'
Cli 3320/3 Finished submitting msg  : <150401c64ee0$56bfa2c9$1d084743@o2.pl>
Cli 3320/3 sent  : Cannot read message data.


[ScalixSupport]

Do you know why there is a {NULL} being sent ?

Cheers

Dave

[vorlon2261]

Can't say that I do... I assume from your question that you doubt they would be part of the email? I've reviewed a couple of hours worth of smtpd.log file entries and its not that common. Only about 8 occurances. Currently a backlog of several hundred messages spanning ~ 5 hours...

The other item that I've noticed is occurances along the lines of:

Code: Select all

Cli 3320/5 rcvd: 'MAIL From:<>'
Cli 3320/5 sent  : 250 ... Sender ok

Cli 3320/5 rcvd: 'RCPT To:<root@mailhost.domain.com>'
Cli 3320/5 sent  : 501 5.5.2 Syntax error in parameters scanning "FROM"

Cli 3320/5 rcvd: 'RSET'
Cli 3320/5 sent  : 250 akiko.unico.com.au Reset state

However these don't revolve around the same errors that have been seen elsewhere in logs...

The only other occurance in the logs is several hundred lines as follows:

Code: Select all

Cli 3320/6 failed: EOF

They usually seem to be preceeded with an RSET after a number of failed attempts to set a MAIL FROM and RCPT TO (usually the MAIL FROM is claimed to be blank by Scalix, though I haven't got any evidence of actual blank from addresses in the emails themselves. Certainly none in the queue at present...

[vorlon2261]

Dave,

Just a thought... Would the Scalix server be attempting any external communications whilst receiving an email? Eg. some mail servers attempt to establish the liegitimacy of the server making the incoming connection, etc...

Am asking because if it is, then its likely that this particular functionality is probably failing...

Greg