[UFO Chicago] ASSP is deleting too much incoming mail

[brian sobolak]

(Sorry for top posting.)

Jay, I suspect that there is greylisting going on. the first time the software sees a triplet (ip, domain, addr) it sends back an unavailable code. Most mail that you want to receive will try again, as it sounds like what happens with guru. 

The 'bad guys' do not try again, abd thus you don't have to store their messages. 

I'm not an ASSP expert, so my reading of this could be wrong. 

Brian 

Sent via BlackBerry from T-Mobile

-----Original Message-----
From: jay at m5.chicago.il.us (Jay F Shachter)

Date: Sun, 22 Jun 2008 23:34:36 
To:ufo at ufo.chicago.il.us
Subject: [UFO Chicago] ASSP is deleting too much incoming mail


Since it was at a ufo meeting that I first learned of ASSP, I
fervently hope that someone on this mailing list will know enough
about ASSP to answer this question.

I am running ASSP in what I believe to be "test mode".  This is the
mode in which one is supposed to run ASSP when one first installs it.
If I understand correctly, when it runs in "test mode" no incoming
mail is supposed to be blocked.  During this initial period, one
categorizes one's incoming mail messages by moving copies of said
messages (which ASSP saves) into the appropriate "spam" or "nospam"
directories, as the case may be.  After accumuluating about 400 or so
properly categorized messages, one build the Bayesian database (by
invoking "perl rebuildspamdb.pl") and then begins to run ASSP in
normal mode, by connecting to the administrative port (55555, by
default) and unchecking the "All Test Mode" checkbox.  At this point,
with the Bayesian database built, ASSP can begin to operate in normal
mode, by discarding incoming mail messages that resemble messages
characterized as "spam" more than they resemble messages characterized
as "nonspam".  This is my understanding of the documentation.  Please
correct me if my understanding is wrong.

(I have set up ASSP so as to accept incoming connections on port 25,
and to communicate with postfix on port 24, and I have set up postfix
so as to accept incoming connections on said port; I am confident that
this part is working correctly.)

To my surprise and bemusement, ASSP has already discarded numerous
incoming messages -- by what criterion, I do not know -- including at
least one message that I wanted to receive.  My logs/maillog.txt file
began to show the following lines soon after my most recent
reconfiguration of ASSP:

 Jun-22-08 19:56:29 Connected: 70.45.6.59:4408 -> 76.197.193.113:25 -> 76.197.193.113:24
 Jun-22-08 19:56:38 70.45.6.59 <bennett_nw at provider.nu> adding new triplet: (70.45.6.0,bennett_nw at provider.nu,jay at m5.chi.il.us)
 Jun-22-08 19:56:38 70.45.6.59 <bennett_nw at provider.nu> recipient delayed: jay at m5.chi.il.us
 Jun-22-08 19:56:38 70.45.6.59 <bennett_nw at provider.nu> is disconnected 
 Jun-22-08 20:01:10 Connected: 41.249.126.208:4490 -> 76.197.193.113:25 -> 76.197.193.113:24
 Jun-22-08 20:01:11 41.249.126.208 <LeonelmooreMcknight at mozilla.com> adding new triplet: (41.249.126.0,leonelmooremcknight at mozilla.com,jay at m5.chi.il.us)
 Jun-22-08 20:01:11 41.249.126.208 <LeonelmooreMcknight at mozilla.com> recipient delayed: jay at m5.chi.il.us
 Jun-22-08 20:01:11 41.249.126.208 <LeonelmooreMcknight at mozilla.com> is disconnected 
 Jun-22-08 20:04:07 Connected: 201.66.80.225:50852 -> 76.197.193.113:25 -> 76.197.193.113:24
 Jun-22-08 20:04:10 201.66.80.225 <mambomc30 at psychographix.com> adding new triplet: (201.66.80.0,mambomc30 at psychographix.com,kaa29326 at m5.chi.il.us)
 Jun-22-08 20:04:10 201.66.80.225 <mambomc30 at psychographix.com> recipient delayed: kaa29326 at m5.chi.il.us
 Jun-22-08 20:04:11 201.66.80.225 <mambomc30 at psychographix.com> is disconnected 
 Jun-22-08 20:04:24 Connected: 200.121.32.96:16071 -> 76.197.193.113:25 -> 76.197.193.113:24
 Jun-22-08 20:04:25 200.121.32.96 <BrandencrueltyMcmillan at sony.com> adding new triplet: (200.121.32.0,brandencrueltymcmillan at sony.com,jay at m5.chi.il.us)
 Jun-22-08 20:04:25 200.121.32.96 <BrandencrueltyMcmillan at sony.com> recipient delayed: jay at m5.chi.il.us
 Jun-22-08 20:04:25 200.121.32.96 <BrandencrueltyMcmillan at sony.com> is disconnected 
 Jun-22-08 20:04:31 Connected: 200.121.219.181:50504 -> 76.197.193.113:25 -> 76.197.193.113:24
 Jun-22-08 20:04:32 200.121.219.181 <BookerhasntChan at greymagic.com> adding new triplet: (200.121.219.0,bookerhasntchan at greymagic.com,leviathan at leviathan.chicago.il.us)
 Jun-22-08 20:04:32 200.121.219.181 <BookerhasntChan at greymagic.com> recipient delayed: leviathan at leviathan.chicago.il.us
 Jun-22-08 20:04:32 200.121.219.181 <BookerhasntChan at greymagic.com> is disconnected 
 Jun-22-08 20:04:36 Connected: 210.3.190.243:3974 -> 76.197.193.113:25 -> 76.197.193.113:24
 Jun-22-08 20:04:37 210.3.190.243 <steilt at psarealty.net> adding new triplet: (210.3.190.0,steilt at psarealty.net,shachterjay at m5.chi.il.us)
 Jun-22-08 20:04:37 210.3.190.243 <steilt at psarealty.net> recipient delayed: shachterjay at m5.chi.il.us
 Jun-22-08 20:04:37 210.3.190.243 <steilt at psarealty.net> is disconnected 

None of these mail messages was ever processed by postfix.  The postfix
logs show that the above-logged events correspond to occasions when
ASSP connected to postfix, and then terminated the connections
prematurely:

 Jun 22 19:56:29 m5 postfix/smtpd[10456]: connect from m5[76.197.193.113]
 Jun 22 19:56:38 m5 postfix/smtpd[10456]: lost connection after MAIL from m5[76.197.193.113]
 Jun 22 19:56:38 m5 postfix/smtpd[10456]: disconnect from m5[76.197.193.113]
 Jun 22 20:01:10 m5 postfix/smtpd[10593]: connect from m5[76.197.193.113]
 Jun 22 20:01:11 m5 postfix/smtpd[10593]: lost connection after MAIL from m5[76.197.193.113]
 Jun 22 20:01:11 m5 postfix/smtpd[10593]: disconnect from m5[76.197.193.113]
 Jun 22 20:04:07 m5 postfix/smtpd[10651]: connect from m5[76.197.193.113]
 Jun 22 20:04:11 m5 postfix/smtpd[10651]: lost connection after MAIL from m5[76.197.193.113]
 Jun 22 20:04:11 m5 postfix/smtpd[10651]: disconnect from m5[76.197.193.113]
 Jun 22 20:04:24 m5 postfix/smtpd[10651]: connect from m5[76.197.193.113]
 Jun 22 20:04:25 m5 postfix/smtpd[10651]: lost connection after MAIL from m5[76.197.193.113]
 Jun 22 20:04:25 m5 postfix/smtpd[10651]: disconnect from m5[76.197.193.113]
 Jun 22 20:04:31 m5 postfix/smtpd[10651]: connect from m5[76.197.193.113]
 Jun 22 20:04:32 m5 postfix/smtpd[10651]: lost connection after MAIL from m5[76.197.193.113]
 Jun 22 20:04:32 m5 postfix/smtpd[10651]: disconnect from m5[76.197.193.113]
 Jun 22 20:04:36 m5 postfix/smtpd[10651]: connect from m5[76.197.193.113]
 Jun 22 20:04:37 m5 postfix/smtpd[10651]: disconnect from m5[76.197.193.113]

Now, I am certain that none of these messages was mail that I wanted
to receive, but I am highly displeased that ASSP undertook to discard
them without my telling it to do so.  How does ASSP know that these
were messages in which I was not interested?  Who authorized it to
discard them without showing them to me?

Moreover, my displeasure is more than theoretical.  In the few hours
that have elapsed since I began to run ASSP, I have evidence that it
deleted at least one incoming message that I wanted to receive:

 Jun-22-08 22:05:07 Connected: 216.151.125.108:52873 -> 76.197.193.113:25 -> 76.197.193.113:24
 Jun-22-08 22:05:07 216.151.125.108 <info at guru.com> adding new triplet: (216.151.125.0,info at guru.com,jay at m5.chi.il.us)
 Jun-22-08 22:05:07 216.151.125.108 <info at guru.com> recipient delayed: jay at m5.chi.il.us
 Jun-22-08 22:05:07 216.151.125.108 <> is disconnected 
 Jun-22-08 22:05:07 Connected: 216.151.125.108:52876 -> 76.197.193.113:25 -> 76.197.193.113:24
 Jun-22-08 22:05:07 216.151.125.108 <info at guru.com> embargoing triplet: (216.151.125.0,info at guru.com,jay at m5.chi.il.us) waited: 0s
 Jun-22-08 22:05:07 216.151.125.108 <info at guru.com> recipient delayed: jay at m5.chi.il.us
 Jun-22-08 22:05:07 216.151.125.108 <> is disconnected 

I want to receive mail from info at guru.com, but ASSP has decided to
discard a message from that sender.  Indeed, my postfix logs report
that, while the above was taking place, ASSP connected to postfix, and
then disconnected from it, twice:

 Jun 22 22:05:07 m5 postfix/smtpd[13214]: connect from m5[76.197.193.113]
 Jun 22 22:05:07 m5 postfix/smtpd[13214]: disconnect from m5[76.197.193.113]
 Jun 22 22:05:07 m5 postfix/smtpd[13214]: connect from m5[76.197.193.113]
 Jun 22 22:05:07 m5 postfix/smtpd[13214]: disconnect from m5[76.197.193.113]

What is particularly puzzling, and for which I have no explanation, is
the following excerpt, from later on in logs/maillog.txt:

 Jun-22-08 22:33:01 Connected: 216.151.125.108:51924 -> 76.197.193.113:25 -> 76.197.193.113:24
 Jun-22-08 22:33:02 216.151.125.108 <info at guru.com> accepting triplet: (216.151.125.0,info at guru.com,jay at m5.chi.il.us) waited: 27m 55s
 Jun-22-08 22:33:02 Commencing DNSBL checks on 216.151.125.108
 Jun-22-08 22:33:02 Completed DNSBL checks on 216.151.125.108
 Jun-22-08 22:33:02 [DNSBL] 216.151.125.108 <info at guru.com> to: jay at m5.chi.il.us DNSBL Received-DNSBL: pass
 Jun-22-08 22:33:02 Commencing DNSBL checks on guru.com
 Jun-22-08 22:33:02 Completed DNSBL checks on guru.com
 Jun-22-08 22:33:02 216.151.125.108 <info at guru.com> to: jay at m5.chi.il.us URIBL Received-URIBL: pass
 Jun-22-08 22:33:02 216.151.125.108 <info at guru.com> to: jay at m5.chi.il.us  Regex:SpamLover 'Password'
 Jun-22-08 22:33:02 [MessageOK] 216.151.125.108 <info at guru.com> to: jay at m5.chi.il.us message ok Project_Notification_  -> ./okmail/Project_Notification_--5.eml
 Jun-22-08 22:33:03 216.151.125.108 <info at guru.com> to: jay at m5.chi.il.us is disconnected

As my postfix logs indicate, the above-logged events correspond to a
successful message delivery:

 Jun 22 22:33:01 m5 postfix/smtpd[13829]: connect from m5[76.197.193.113]
 Jun 22 22:33:02 m5 postfix/smtpd[13829]: 121D0C29DD: client=m5[76.197.193.113]
 Jun 22 22:33:02 m5 postfix/cleanup[13847]: 121D0C29DD: message-id=<8810792.1214187640796.JavaMail.aspnetlogin at guru-vh01-bkweb>
 Jun 22 22:33:03 m5 postfix/qmgr[7312]: 121D0C29DD: from=<info at guru.com>, size=8040, nrcpt=1 (queue active)
 Jun 22 22:33:03 m5 postfix/smtpd[13829]: disconnect from m5[76.197.193.113]
 Jun 22 22:33:03 m5 postfix/local[13848]: 121D0C29DD: to=<jay at m5.chi.il.us>, relay=local, delay=2, status=sent (delivered to command: /opt/jay/Linux2/bin/filter -Vo /tmp/Filter.out)
 Jun 22 22:33:03 m5 postfix/qmgr[7312]: 121D0C29DD: removed

It appears from the above that info at guru.com re-transmitted its mail
message to me, 27 minutes and 55 seconds after its first attempt to do
so was thwarted by ASSP; the re-transmitted mail was successfully
delivered.  This is my guess of what happened, based on what I can
decipher from the above logs.  It appears that in the case of this one
mail message, nothing was permanently lost, because the sender was
kind enough to attempt a retransmission.  But ASSP's first capricious
deletion of the message resulted in a delay of 27 minutes and 55
seconds before my receipt of the re-transmitted message.  It is
frequently important (especially in the case of mail sent from
info at guru.com) that mail sent to me now be received now.-- now, not 27
minutes and 55 seconds from now.  And it seems that the message was
received at all only because the sender was courteous enough to
attempt to retransmit it; had no retransmission attempt occurred, the
mail would have been irretrievably lost, as were all of the other mail
messages that ASSP discarded without authorization from me.

I have considered the possibility that the "All Test Mode" checkbox,
one component of the form that my web browser shows me when it
connects to http://127.0.0.1:55555, and which I have checked, does
not, in fact, imply, despite its name, that all the other test modes
are in force.  Even after checking "All Test Mode", there are other
test mode checkboxes (e.g., "BlackDomain Test Mode", "Helo-Blacklist
Test Mode", "Spam Address Test Mode", "SPF Test Mode", "DNSBL Test
Mode", "Bad Attachment Test Mode", "URIBL Test Mode") that remain
unchecked.  But even if these other test modes are not implied by "All
Test Mode", and consequently are not in force, that does not explain
why ASSP would discard or delay mail messages that I never authorized
it to discard or delay.

If you can explain to me why ASSP is acting as it does, and what I
must do to get it to stop doing so. I shall greatly appreciate your
enlightening me.  I thank you in advance for your reply.


			Jay F. Shachter
			6424 N Whipple St
			Chicago IL  60645-4111
				(1-773)7613784
				jay at m5.chicago.il.us
				http://m5.chicago.il.us

			"Quidquid latine dictum sit, altum videtur"
_______________________________________________
UFO Chicago -- Users of Free Operating Systems
Free Software Rules -- Proprietary Drools!
http://ufo.chicago.il.us/cgi-bin/mailman/listinfo/ufo