SMTP Aborting...

[kanderson]

I have a server where SMTPD is aborting. I'm not too sure why.

It seems to be semi-random, but much more frequently lately. I've added a script to detect it and restart it automatically, but I'd like to know why it's happening at all.

The fatal log for the most recent abort shows...


SERIOUS ERROR Internet Mail (Incoming ) Tue Aug 22 12:50:30 2006
[OM 10270] Process about to terminate due to error.
Signal (Abort) trapped by process 8515
Procedure trace follows:
-> mim_ListTypesFile
<- mim_ListTypesFile
-> mim_GetCharSetName
<- mim_GetCharSetName
<- mim_MimeToOMType
-> im_GetNewItemNum
<- im_GetNewItemNum
-> mim_DecodeMimeFile
<- mim_DecodeMimeFile
-> im_ItemRef2FName
<- im_ItemRef2FName
-> ux_CnvFileToString
<- ux_CnvFileToString
-> mapi_IcalToSxProps
-> mapi_icalTimeType2UtcString
<- mapi_icalTimeType2UtcString
Pid of logging process: 8515


SERIOUS ERROR Internet Mail (Incoming ) Tue Aug 22 12:50:30 2006
[OM 10272] BACKTRACE:
/opt/scalix/lib/libom_er.so(er_add_backtrace+0xc6)[0x4009e3f6]
/opt/scalix/lib/libom_er.so[0x4009e6c5]
/opt/scalix/lib/libom_er.so(er_DumpProcAndExit+0x1f)[0x4009e84f]
[0xffffe420]
/lib/tls/libc.so.6(abort+0x1a5)[0x401d0e65]
/lib/tls/libc.so.6(__assert_fail+0x103)[0x401c8c03]
/usr/lib/libical.so.0[0x4069b67b]
/usr/lib/libical.so.0(icalcomponent_new_clone+0xd0)[0x40696640]
/opt/scalix/lib/libom_mapi.so(mapi_IcalToSxProps+0x159d)[0x400e659d]
/opt/scalix/bin/unix.in[0x805a355]
/opt/scalix/bin/unix.in[0x805fdb6]
/opt/scalix/bin/unix.in[0x8053bb4]
/opt/scalix/bin/unix.in[0x804f27c]
/opt/scalix/bin/unix.in[0x804c8b3]
/opt/scalix/lib/libom_cl.so(cl_CallProc+0x87)[0x400303e3]
/opt/scalix/bin/unix.in[0x8056746]
/lib/tls/libc.so.6(__libc_start_main+0xd0)[0x401bd210]
/opt/scalix/bin/unix.in[0x804c481]
Pid of logging process: 8515


Any suggestions would me greatly appreciated.

Thanks
Kev.

[dkelly]

Are you able to keep smtpd debug logging running long enough to capture a problem message ?

Cheers

Dave

[kanderson]

Will try. I should have you one in a day or two.

Thanks
Kev.

[kanderson]

Well, that didn't take long...

The entire log is about 250 Megs, so I'm not going to post all of it.

Below is what I thought would be relevant. It's about the last 80 or 100 lines.

flowers@midwesturveys is not a valid email address, even if the domain was corrected. The user "flowers" (or flower, or anything like it) does not exist. (I've changed all of the email addresses to be missing a domain letter)

Thanks in advance.
Kev.



Accepted client 1 from ()
Cli 2423/1 sent : 220 msicalmail.midwesturveys.com ESMTP Scalix SMTP Relay 10.0.1.3; Wed, 23 Aug 2006 05:32:31 -0600 (MDT)

Cli 2423/1 rcvd: 'EHLO MWbarracuda.midwesturveys.com'
Cli 2423/1 sent : 250-msicalmail.midwesturveys.com Hello [198.161.10.45], pleased to meet you
250-AUTH CRAM-MD5 DIGEST-MD5 LOGIN PLAIN GSSAPI
250-AUTH=LOGIN
250-DSN
250 8BITMIME

Cli 2423/1 rcvd: 'MAIL FROM:<postmaster@barracudaetworks.com>'
Cli 2423/1 sent : 250 postmaster@barracudaetworks.com... Sender ok

Cli 2423/1 rcvd: 'RCPT TO:<euresti@midwesturveys.com>'
... new process 4709
2423: Allocate new unix.in process 4709
Cli 2423/1 rcvd U: '220 Scalix ESMTP Ready.'
Cli 2423/1 rcvd U: '250 Ok'
Cli 2423/1 sent U: rcpt to: <euresti@midwesturveys.com>

Cli 2423/1 rcvd U: '250 Ok'
Cli 2423/1 sent : 250 Ok

Cli 2423/1 rcvd: 'RCPT TO:<dixon@midwesturveys.com>'
Cli 2423/1 sent U: rcpt to: <dixon@midwesturveys.com>

Cli 2423/1 rcvd U: '250 Ok'
Cli 2423/1 sent : 250 Ok

Cli 2423/1 rcvd: 'RCPT TO:<arnold@midwesturveys.com>'
Cli 2423/1 sent U: rcpt to: <arnold@midwesturveys.com>

Cli 2423/1 rcvd U: '250 Ok'
Cli 2423/1 sent : 250 Ok

Accepted client 4 from ()
Cli 2423/4 sent : 220 msicalmail.midwesturveys.com ESMTP Scalix SMTP Relay 10.0.1.3; Wed, 23 Aug 2006 05:32:35 -0600 (MDT)

Cli 2423/4 rcvd: 'EHLO MWbarracuda.midwesturveys.com'
Cli 2423/4 sent : 250-msicalmail.midwesturveys.com Hello [198.161.10.45], pleased to meet you
250-AUTH CRAM-MD5 DIGEST-MD5 LOGIN PLAIN GSSAPI
250-AUTH=LOGIN
250-DSN
250 8BITMIME

Cli 2423/4 rcvd: 'MAIL FROM:<cavalry@altelansing.com>'
Cli 2423/4 sent : 250 cavalry@altelansing.com... Sender ok

Cli 2423/4 rcvd: 'RCPT TO:<arnold@midwesturveys.com>'
... new process 4713
2423: Allocate new unix.in process 4713
Cli 2423/4 rcvd U: '220 Scalix ESMTP Ready.'
Cli 2423/4 rcvd U: '250 Ok'
Cli 2423/4 sent U: rcpt to: <arnold@midwesturveys.com>

Cli 2423/4 rcvd U: '250 Ok'
Cli 2423/4 sent : 250 Ok

Cli 2423/4 rcvd: 'RCPT TO:<coleman@midwesturveys.com>'
Cli 2423/4 sent U: rcpt to: <coleman@midwesturveys.com>

Cli 2423/4 rcvd U: '250 Ok'
Cli 2423/4 sent : 250 Ok

Cli 2423/4 rcvd: 'RCPT TO:<dixon@midwesturveys.com>'
Cli 2423/4 sent U: rcpt to: <dixon@midwesturveys.com>

Cli 2423/4 rcvd U: '250 Ok'
Cli 2423/4 sent : 250 Ok

Cli 2423/4 rcvd: 'RCPT TO:<euresti@midwesturveys.com>'
Cli 2423/4 sent U: rcpt to: <euresti@midwesturveys.com>

Cli 2423/4 rcvd U: '250 Ok'
Cli 2423/4 sent : 250 Ok

Cli 2423/4 rcvd: 'RCPT TO:<flowers@midwesturveys.com>'
SMTP Relay 10.0.1.3 finished (2423): Wed, 23 Aug 2006 05:32:35 -0600 (MDT)

[dkelly]

The SMTP Relay will call sendmail to check if a non-Scalix user is known outside of Scalix. So, can you check your sendmail log to see if there are any errors recorded there.

Is this something you can reproduce via a telnet session using only the 'flowers' address ?

Cheers

Dave

[kanderson]

Here's what the sendmail log shows... when I grep for flower.

Thanks
Kev.


Aug 23 06:03:53 msicalmail sendmail[6499]: k7NC3rNA006499: to=<arnold@midwestsurveys.com>,<coleman@midwestsurveys.com>,<dixon@midwestsurveys.com>,<euresti@midwestsurveys.com>,<flowers@midwestsurveys.com>,<gryniuk@midwestsurveys.com>,<mann@midwestsurveys.com>,<mcgee@midwestsurveys.com>,<ristig@midwestsurveys.com>,<rsehn@midwestsurveys.com>,<shoener@midwestsurveys.com>, delay=00:00:00, xdelay=00:00:00, mailer=relay, pri=332232, relay=[127.0.0.1] [127.0.0.1], dsn=4.0.0, stat=Deferred: Connection refused by [127.0.0.1]
Aug 23 06:16:52 msicalmail sendmail-client[3369]: k7NC3rNA006499: to=<arnold@midwestsurveys.com>,<coleman@midwestsurveys.com>,<dixon@midwestsurveys.com>,<euresti@midwestsurveys.com>,<flowers@midwestsurveys.com>,<gryniuk@midwestsurveys.com>,<mann@midwestsurveys.com>,<mcgee@midwestsurveys.com>,<ristig@midwestsurveys.com>,<rsehn@midwestsurveys.com>,<shoener@midwestsurveys.com>, delay=00:12:59, xdelay=00:00:00, mailer=relay, pri=422232, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0, stat=Sent (k7NCGosT007315 Message accepted for delivery)
Aug 23 06:16:58 msicalmail sendmail[7370]: k7NCGosT007315: to=<flowers@midwestsurveys.com>, delay=00:00:06, xdelay=00:00:06, mailer=esmtp, pri=422495, relay=mx.cal.terago.ca. [207.54.98.227], dsn=4.2.0, stat=Deferred: 450 <flowers@midwestsurveys.com>: Recipient address rejected: Policy Rejection- Please try later.
Aug 23 06:20:50 msicalmail sendmail[7559]: k7NCGosT007315: to=<flowers@midwestsurveys.com>, delay=00:03:58, xdelay=00:00:02, mailer=esmtp, pri=512495, relay=mx.cal.terago.ca. [207.54.98.227], dsn=4.2.0, stat=Deferred: 450 <flowers@midwestsurveys.com>: Recipient address rejected: Policy Rejection- Please try later.
Aug 23 06:50:47 msicalmail sendmail[8990]: k7NCGosT007315: to=<arnold@midwestsurveys.com>,<coleman@midwestsurveys.com>,<dixon@midwestsurveys.com>,<euresti@midwestsurveys.com>,<flowers@midwestsurveys.com>,<gryniuk@midwestsurveys.com>,<mann@midwestsurveys.com>,<mcgee@midwestsurveys.com>,<ristig@midwestsurveys.com>,<rsehn@midwestsurveys.com>,<shoener@midwestsurveys.com>, delay=00:33:55, xdelay=00:00:00, mailer=esmtp, pri=602495, relay=mx.cal.terago.ca., dsn=5.3.0, stat=Internal error

[dkelly]

What MTA is mx.cal.terago.ca ? A 4xx return code is a transient error rather than a hard error and is different from the usual "User unknown" return codes.

Cheers

Dave

[kanderson]

It looks like it's looping...

mx.cal.terago.ca is the ISP's SMTP. All inbound email is delivered to them, then sent to a barracuda filter, then to Scalix. This allows the ISP to queue their messages in the event of an outage.

So I'll guess that the message comes in to the ISP, then the 'cuda, then Scalix, then goes to Sendmail, then to the ISP, and the process repeats.

I checked /etc/mail/local-host-names, and sure enough, they had the external DNS name for their server. I've added their domain name, and the internal name. Hopefully that'll at least cause a rejection if the recip is bad.

I'm still waiting for another abort, and I still have it building (a massive) smtpd.log file. But let's see how this goes. I don't think that would cause smtpd to abort, it would just create a loop, right?

Thanks
Kev.

[dkelly]

You didn't say whether you can reproduce this with a telnet SMTP session to the Scalix server.

Cheers

Dave

[kanderson]

I put the local-host-names back, and then send a test message to flowers via telnet.

The telnet session eventually looped and timed out, smtpd did not crash.

I'll put local-host-names back again...

Kev.