this looks identical to the problem i was seeing in 2.63 that i was not having
in 3.0 last i tested (r9952)

from the sa-talk list a couple days ago...

################
I'm having a problem with mail containing the following received header
from ever processing.   It takes 70-80 seconds for SA 2.63 to process it
which exceeds by spamc -t60 therefore it exits 74 and tempfails it.
This happens over and over all day long.   Testing this through 3.0-SVN
the message scans in just a couple seconds...  Is there an easy fix for this on
2.63, besides enabling -L for spamd (which works).

FROM 2.63
--------------------

# cat /tmp/message
Received: from e2kdfwmcs1.fhhlc.ftn.com ([10.40.34.13]) by 
e2kmemsmtp1.ftbco.ftn.com with Microsoft SMTPSVC(5.0.2195.6713); Thu,  15 Apr
2004 11:27:07 -0500

Hi

[root@mailgw tmp]# spamassassin -V
SpamAssassin version 2.63

[root@mailgw tmp]# time spamc -t60 < /tmp/message
Received: from e2kdfwmcs1.fhhlc.ftn.com ([10.40.34.13]) by 
e2kmemsmtp1.ftbco.ftn.com with Microsoft SMTPSVC(5.0.2195.6713); Thu,  15 Apr
2004 11:27:07 -0500

Hi

real    1m46.338s
user    0m0.000s
sys     0m0.000s

FROM 3.0 SVN
--------------------

[root@spamd4 tmp]# spamassassin -V
SpamAssassin version 3.0.0-r9952

[root@spamd4 tmp]# time spamc -t60 < /tmp/message
Received: from e2kdfwmcs1.fhhlc.ftn.com ([10.40.34.13]) by 
e2kmemsmtp1.ftbco.ftn.com with Microsoft SMTPSVC(5.0.2195.6713); Thu,  15 Apr
2004 11:27:07 -0500
X-Spam-Level: **
X-Spam-Status: No, hits=2.9 required=5.0

Hi

real    0m3.819s
user    0m0.000s
sys     0m0.000s

--------------------

when i was seeing the problem, I believe it is related to a non-existent domain
or a domain that doesnt not have DNS servers answering requests, therefore spamd
was waiting for a DNS timeout from the OS..  

At least when I was experiencing the problem with my received header hanging (by
watching spamd debug log), i could not do any lookups on NS's for ftn.com,
nmap'ing port 53udp on their NS's said filtered.  It looks like they might have
a valid NS in there now.

Is putting an eval {};  on the Received header DNS lookups in order to associate
a user-defined timeout worth having?   We have razor_timeout, pyzor_timeout,
dcc_timeout,  why not a dns_timeout?

 

I do not think it is a DNS lookup timeout problem. The latest example only took
28s from the time of the incoming connection to sendmail to the mail being
delivered by procmail.

I only started seeing this with the spamd which pre-forks. I never saw it with
the previous 3.0.0 versions of spamd.

does the same message repeatedly have this behavior?

I saved one of the messages showing this problem and ran it through spamc
manually. I did this 5 times, 2 times it came back with X-SPAM headers, 3 times
it came back with no added headers.

Also looking at another message which failed, it is not always stopping at the
'Received-header parsed", At least one message stopped after "Running tests for
priority: 500" but again I do not think this is a timeout as the message was
only a few seconds into processing.

well, that ftn.com received header is doing the same thing again on 2.63 -
testing the same message as you see above in this bug with just the single
received header line and the word 'Hi' in the body... it causes spamc to return
after 60 seconds from -t60, and spamd finally finishes the processing in 1
minute and 36 seconds as you'll see by the debug log for PID 13883...

it hangs on the 'debug: received-header:' twice as you can see, for 51 seconds
on the first, and 52 seconds on the second... sure sounds like a dns timeout of
some kind to me since they are so close.

[root@mailgw root]# time spamc -t60 < /tmp/message
Received: from e2kdfwmcs1.fhhlc.ftn.com ([10.40.34.13]) by
 e2kmemsmtp1.ftbco.ftn.com with Microsoft SMTPSVC(5.0.2195.6713); Thu,
 15 Apr 2004 11:27:07 -0500

Hi


real    1m0.007s
user    0m0.000s
sys     0m0.000s


debug info where it was hanging..
-------------------------------
..
..
2004-04-19 07:01:42.954209500 debug: bayes: 13883 untie-ing db_toks
2004-04-19 07:01:42.954339500 debug: bayes: 13883 untie-ing db_seen
2004-04-19 07:01:42.955358500 debug: received-header: parsed as [ ip=10.40.34.13
rdns=e2kdfwmcs1.fhhlc.ftn.com helo= by=e2kmemsmtp1.ftbco.ftn.com ident= ]
2004-04-19 07:02:33.989726500 debug: received-header: 'from' 10.40.34.13 has
reserved IP
2004-04-19 07:03:25.979742500 debug: received-header: relay 10.40.34.13 trusted? yes
2004-04-19 07:03:25.980736500 debug: Message too short for language analysis
..
..
2004-04-19 07:03:29.361244500 logmsg: clean message (2.9/4.0) for root:99 in
106.4 seconds, 163 bytes.
2004-04-19 07:03:29.361246500 debug: cleaned up kid 13883, pool=5
---------------------

also, if spamc detaches, why does spamd keep processing?  should the timeout be
server side on spamd instead of client side on spamc?

taking the tickets since they're all related to the new spamd...

btw, would suggest attaching a sample

this looks exactly like the 3317 bug.

*** This bug has been marked as a duplicate of 3317 ***