Found nn messages in the processing-messages database

[Kai Schaetzl]

ailScanner|ecs.soton.ac.uk|040707 at ecs.soton.ac.uk>
Reply-To: mailscanner at lists.mailscanner.info

Julian Field wrote on Fri, 17 Apr 2009 14:00:16 +0100:

> Are there any other mentions of the first one of these? The second one 
> is a different message (note the different random tag number on the end).

I think it is the same, that's why I quoted both here.

This is from the postfix log:

Mar 30 04:11:50 d01 postfix/smtpd[9789]: connect from 
udp287212uds.hawaiiantel.net[72.253.249.143]
Mar 30 04:11:51 d01 postfix/smtpd[9789]: B48BFF9477: 
client=udp287212uds.hawaiiantel.net[72.253.249.143]
Mar 30 04:11:52 d01 postfix/cleanup[9845]: B48BFF9477: hold: header Received: 
from udp287212uds.hawaiiantel.net (udp287212uds.hawaiiantel.net 
[72.253.249.143])??by mailer.example.com (Postfix) with ESMTP id B48BFF9477??
for <clubie1 at example.com>; Mon, 30 Mar 2009 04: from 
udp287212uds.hawaiiantel.net[72.253.249.143]; from=<umw at bluebeatmusic.com> 
to=<clubie1 at example.com> proto=ESMTP helo=<udp287212uds.hawaiiantel.net>
Mar 30 04:11:52 d01 postfix/cleanup[9845]: B48BFF9477: message-
id=<000d01c9b0dc$cf4e03e0$6400a8c0 at umw>
Mar 30 04:11:54 d01 postfix/smtpd[9789]: disconnect from 
udp287212uds.hawaiiantel.net[72.253.249.143]
Mar 30 04:11:54 d01 postfix/postfix-script: refreshing the Postfix mail system

Notice the last line. Any chance this triggered it? This is a reload of the 
configuration and some statistical output. Maybe it also kills childs and 
loads new ones, don't know. A locking problem, so that MS couldn't process it 
the first time?

> > Mar 30 04:12:02 d01 MailScanner[9923]: Logging message B48BFF9477.D962D to
> > SQL
> > Mar 30 04:12:02 d01 MailScanner[9925]: B48BFF9477.D962D: Logged to
> > MailWatch SQL
  
> The first message or the second one? It does seem slightly odd that the 
> same inode number turned up twice in such quick succession. Are you sure 
> these two messages are actually different messages, or are they the same 
> one, and the first processing of it was abandoned for some reason?

I thought it was clear that I think/know it is one message, sorry, if that 
wasn't clear. Here's the complete sequence from the mailscanner.log. It didn't 
appear to me that just grepping for the id wouldn't reveal everything ;-)
Yes, it seems, the processing got abandoned. But shouldn't it then get 
removed? 

Mar 30 04:11:53 d01 MailScanner[879]: New Batch: Scanning 1 messages, 21465 
bytes
Mar 30 04:11:53 d01 MailScanner[879]: Saved archive copies of B48BFF9477.51697
Mar 30 04:11:53 d01 MailScanner[879]: MailScanner child caught a SIGHUP
Mar 30 04:11:53 d01 MailScanner[879]: Config: calling custom end function 
MailWatchLogging
Mar 30 04:11:54 d01 MailScanner[9901]: MailScanner child caught a SIGHUP
Mar 30 04:11:54 d01 MailScanner[9901]: Config: calling custom end function 
MailWatchLogging
Mar 30 04:11:56 d01 MailScanner[9923]: MailScanner E-Mail Virus Scanner 
version 4.75.9 starting...
<yadayadayada>
Mar 30 04:12:01 d01 MailScanner[9923]: Connected to processing-messages 
database
Mar 30 04:12:01 d01 MailScanner[9923]: Found 1 messages in the processing-
messages database
Mar 30 04:12:01 d01 MailScanner[9923]: Using locktype = flock
Mar 30 04:12:01 d01 MailScanner[9923]: New Batch: Scanning 2 messages, 51210 
bytes
Mar 30 04:12:01 d01 MailScanner[9923]: Saved archive copies of 
B48BFF9477.D962D 4D299F9478.973F1
Mar 30 04:12:02 d01 MailScanner[9923]: Spam Checks: Found 1 spam messages
Mar 30 04:12:02 d01 MailScanner[9923]: Requeue: 4D299F9478.973F1 to 141B3F9307
Mar 30 04:12:02 d01 MailScanner[9923]: Unscanned: Delivered 1 messages

That second message was cron generated and not scanned as local.

Mar 30 04:12:02 d01 MailScanner[9923]: Virus and Content Scanning: Starting
Mar 30 04:12:02 d01 MailScanner[9923]: Deleted 2 messages from processing-
database
Mar 30 04:12:02 d01 MailScanner[9923]: Logging message B48BFF9477.D962D to SQL
Mar 30 04:12:02 d01 MailScanner[9923]: Logging message 4D299F9478.973F1 to SQL
Mar 30 04:12:02 d01 MailScanner[9925]: B48BFF9477.D962D: Logged to MailWatch 
SQL
Mar 30 04:12:02 d01 MailScanner[9925]: 4D299F9478.973F1: Logged to MailWatch 
SQL

Maybe it grabbed B48BFF9477.51697 from the database and then tried to remove 
B48BFF9477.D962D ?

> 
> It just occurred to me that the processing database won't work well with 
> Postfix at all.
> Postfix re-uses the message id numbers too fast for them to be 
> considered good ids, which is why I have to add a random number to the end.
> But I add a new random number to the end every time I pick up the 
> message, so every time it sees the same message it will create different 
> message ids for it.
> So the processing database idea breaks down :-(
> Poo :-(

But this shouldn't be the case here, right? And I don't see evidence that it 
reuses these ids "too fast". I can't see a reuse for these ids for the whole 
month.

Kai

-- 
Kai Schätzl, Berlin, Germany
Get your web at Conactive Internet Services: http://www.conactive.com