[Greylist-users] relaydelay: Sendmail::Milter problem?

[susan barnes]

Hello all,
	

I have given greylisting another try:

relaydelay runs on a linux-box for testing purposes. Everything worked fine.

I have tried to move the same configuration (setting delay to 0) onto one of our real mailservers and run into this problem, which I could reproduce on the test-system as well:


System for Testing:
Linux  (2.4.20)
Sendmail 8.12.8
started with perl 5.8.0, upgraded to 5.8.5
about 200-300 messages/h (it is a kind of spamtrap)

Problem: sendmail-logfile and the relaydelay database differ, that is somehow relaydelay logs some mails more than once and forgets about others. (I assume that sendmail does log correctly)

To check what is happening I have added detailed logging to using Unix::Syslog
(Side-note: Using Unix::Syslog makes relaydelay crash every few hours with a segmentation-fault, although it claims to be threadsafe)

As far as I can see this is not a problem of relay-delay.pl, but somehow the underlying sendmail::milter module does not work as expected. A running thread can alternate between callbacks of two different connections and those connections then share their privdata. This normally occurs between envrcpt- and eom-callback, when mail is passed. Possibly because it takes a bit of time to transmit the DATA-block.



The result is as follows (I have tried to make the log as easy to read as possible)

This is what sendmail sees:

Aug 30 12:15:33 sendmail[1] :qid1: from=<sender1>,..,relay=ip1
Aug 30 12:15:34 sendmail[1] :qid1: to=<recpt1>,..,relay=my_ip

Aug 30 12:15:34 sendmail[2] :qid2: from=<sender2>,..,relay=ip2
Aug 30 12:15:35 sendmail[2] :qid2: to=<recpt2>,..,relay=my_ip



This is what happens in relaydelay.pl

First we have connection 1:

Aug 30 12:15:12 envfrom: args=sender1
Aug 30 12:15:12 envfrom: writing 0\x00<sender1>\x00 into privdata

Aug 30 12:15:21 envrcpt: args=recpt1
Aug 30 12:15:21 envrcpt: privdata=0\x00<sender1>\x00
Aug 30 12:15:21 envrcpt: new mail, adding triple: ip1, sender1, rcpt1
Aug 30 12:15:21 envrcpt: delay is 0 (training): PASS MAIL
Aug 30 12:15:21 envrcpt: writing 4\x00<sender1>\x00<rcpt1> to privdata

seems ok, but then:

Aug 30 12:15:33 eom
Aug 30 12:15:33 eom: privdata :contains 8\x00<sender2>\x00<rcpt2>
Aug 30 12:15:33 eom: undefining privdata
Aug 30 12:15:33 eom: updated row:8

How do I know that this is the eom-callback belonging to the above connection?
I have omitted a line with all sendmail-macros known to the callback, which clearly show that this is eom of connection 1.



This is connection 2 (note the time, I have seperated the two connections logically, chronological they are parallel)

Aug 30 12:15:27 envfrom: args=<sender2>
Aug 30 12:15:27 envfrom: writing 0\x00<sender2>\x00 to privdata.

Aug 30 12:15:29 envrcpt: args=<rcpt2>
Aug 30 12:15:29 envrcpt: privdata=0\x00<sender2>\x00
Aug 30 12:15:29 envrcpt: new mail, adding triple: ip2, sender2, rcpt2
Aug 30 12:15:29 envrcpt: delay is 0 (training): PASS MAIL
Aug 30 12:15:29 envrcpt: writing 8\x00<sender2>\x00<rcpt2> to privdata

Aug 30 12:15:34 eom: privdata :contains 8\x00<sender2>\x00<rcpt2>
Aug 30 12:15:34 eom: undefining privdata
Aug 30 12:15:35 eom: updated row:8

(and why did the undefining of privdata in connection 1 not work?)



Result:
We have row 4 with passed:0, blocked:0 aborted:0 and therefore is still blocked.
We have row 8 with passed:2, blocked:0 aborted:0 which is cleared.


Does anyone have an explanation for this behaviour?
Is there something wrong with my setup or can anyone reproduce this?


Regards
Susan

-- 
Susan Barnes <S.Barnes at rrz.uni-koeln.de>
(postmaster / listmaster services)
Zentrum fuer Angewandte Informatik - Universitaetsweiter Service RRZK
Universitaet zu Koeln / Cologne University        - Tel:0221-478-5594