Found nn messages in the processing-messages database

[Julian Field]

On 17/04/2009 15:29, Kai Schaetzl wrote:
> 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?
Very likely. I don't know what that line means, but it doesn't sound 
good does 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?
>    
Possibly...
>    
>>> 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?
>    
Yes, it should. There's an exit condition I have missed somewhere. I 
will try to find time this weekend to see if I can find it, it is going 
to be pretty well-buried though as I covered the code fairly hard the 
first time. (Having said that of course, I'll find it staring me in the 
face :-)

> 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 ?
>    
Shouldn't do, know. The 5 characters on the end are added right at the 
creation of the message in the batch, it's all part of the MailScanner 
message-id.
>    
>> 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.
>    
It certainly used to, that's why I had to add the random characters on 
the end. I had more messages coming in with the same id in high load 
environments, so had to produce a better unique key for each message. I 
don't want to change that, as it was very definitely necessary at the 
time and so is still necessary on some systems. Maybe ones with small 
queue filesystems?

Jules

-- 
Julian Field MEng CITP CEng
www.MailScanner.info
Buy the MailScanner book at www.MailScanner.info/store

Need help customising MailScanner?
Contact me!
Need help fixing or optimising your systems?
Contact me!
Need help getting you started solving new requirements from your boss?
Contact me!

PGP footprint: EE81 D763 3DB0 0BFD E1DC 7222 11F6 5947 1415 B654


-- 
This message has been scanned for viruses and
dangerous content by MailScanner, and is
believed to be clean.