Found nn messages in the processing-messages database

Fri Apr 17 10:02:47 IST 2009

If "MailScanner --processing=1" produces no output, then the records in 
the database cannot have a count of 1 (the 2nd number in each column in 
your table of 26 database entries below). So when you do that, the only 
records in there must have a value of 0, which means they should have 
been removed.

However, when a child starts up, there will be all the messages in the 
"processing" database table that are currently being processed by other 
MailScanner children. Are you sure there are no other children running 
when that child starts? Also, please look at the output of "MailScanner 
--processing=0" as this will show you all the records in there, which 
the timestamps converted into something readable, rather than the raw 
time_t values you have included. That will let us see if they are in the 
future or way in the past.

I cannot find any situation where the records would fail to be deleted, 
if it says it has deleted them. The only way that can happen is if the 
message id was blank, and all the records in your "processing" database 
table you included below all have non-blank message ids, so it isn't that.

The code for clearing out the database table is pretty straightforward, 
please take a look at it yourself and see if you agree with me. It 
starts at "sub ClearOutProcessedDatabase {" in 
/usr/lib/MailScanner/MailScanner/MessageBatch.pm. If you can see any 
bugs or holes in there, please do tell me!

Thanks,
Jules.

On 17/4/09 03:57, Mark Sapiro wrote:
> On Wed, Apr 15, 2009 at 07:37:49AM -0700, Mark Sapiro wrote:
>    
>> Note that the "Found" count doesn't always increase between restarts, but
>> it never decreases. Also, "New Batch: Scanning X messages" in the log are
>> always followed by "Deleted X messages from processing-database" with the
>> same count and over any period, the "Deleted" counts add up to the same
>> total as the "Scanning" counts even where the "Found" count has increased.
>>      
>
> I've done some additional investigation.
>
> The log messages when a child starts are now up to "Found 26 mmessages
> in the processing-messages database"
>
> Here are the 26 database entries:
>
> 67650690405.93175|1|1239641743
> 92295690444.31465|1|1239641635
> 41537690424.26867|1|1239647420
> 02842690389.04452|1|1239648522
> 57067690409.E4302|1|1239648722
> 16020690433.44254|1|1239648562
> 17300690390.3E804|1|1239671344
> 39224690405.41276|1|1239671354
> 49358690409.95149|1|1239671419
> 99351690429.04632|1|1239678343
> 88257690407.10923|1|1239681381
> 39387690388.E1611|1|1239686821
> 41693690392.32976|1|1239705347
> 49903690394.76309|1|1239705280
> 77828690380.26107|1|1239721588
> 95835690388.E2978|1|1239721567
> 00524690436.5E971|1|1239729939
> 06766690387.55E20|1|1239744929
> 06950690412.30E45|1|1239744996
> 87926690445.21751|1|1239747646
> 35592690431.581E1|1|1239747533
> 00894690425.97190|1|1239747558
> 42214690429.67487|1|1239761289
> 23751690385.34301|1|1239812982
> 97480690403.80930|1|1239906903
> 34979690423.56858|1|1239906907
>
> The timestamps appear a bit off from the timestamps in the maillog
> (perhaps they are "expiration times"), but I can correlate each entry
> to a message that was processed by Mailscanner.
>
> The situation that appears to cause a database entry to be "forgotten"
> is when Mailman sends a large number of messages.
>
> I have scan.messages rules to not scan locally originated mail.
> Mailman does it's VERP like processing so it sends a separate message
> to each recipient. There is one MailScanner child.
>
> Looking at the last two entries with time stamps of 1239906903 =
> Thu Apr 16 11:35:03 local time and 1239906907 = Thu Apr 16 11:35:07
> local time, I see the following sets of maillog entries for those
> Postfix queue IDs (addresses sanitized).
>
> Apr 16 11:31:31 sbh16 postfix/smtpd[7846]: 97480690403: client=localhost.localdomain[127.0.0.1]
> Apr 16 11:31:31 sbh16 postfix/cleanup[8793]: 97480690403: hold: header Received: from sbh16.songbird.com (localhost.localdomain [127.0.0.1])??by sbh16.songbird.com (Postfix) with ESMTP id 97480690403??for<u1 at example.com>; Thu, 16 Apr 2009 11:31:31 -0700 (PDT) from localhost.localdomain[127.0.0.1]; from=<gpc-talk-bounces+u1=example.com at grizz.org>  to=<u1 at example.com>  proto=ESMTP helo=<sbh16.songbird.com>
> Apr 16 11:31:31 sbh16 postfix/cleanup[8793]: 97480690403: message-id=<8CB8CD89509361E-684-1921 at WEBMAIL-MB13.sysops.aol.com>
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 97480690403.80930 to E531F6903BA
>
> and
>
> Apr 16 11:31:32 sbh16 postfix/smtpd[7846]: 34979690423: client=localhost.localdomain[127.0.0.1]
> Apr 16 11:31:32 sbh16 postfix/cleanup[8803]: 34979690423: hold: header Received: from sbh16.songbird.com (localhost.localdomain [127.0.0.1])??by sbh16.songbird.com (Postfix) with ESMTP id 34979690423??for<u2 at example.com>; Thu, 16 Apr 2009 11:31:32 -0700 (PDT) from localhost.localdomain[127.0.0.1]; from=<gpc-talk-bounces+u2=example.com at grizz.org>  to=<u2 at example.com>  proto=ESMTP helo=<sbh16.songbird.com>
> Apr 16 11:31:32 sbh16 postfix/cleanup[8803]: 34979690423: message-id=<8CB8CD89509361E-684-1921 at WEBMAIL-MB13.sysops.aol.com>
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 34979690423.56858 to 1F3606903C6
>
> The entire set of MailScanner messages in maillog starting with the
> start of the batch containing the first of the two messages and ending
> with the end of the batch containing the second of the two messages is
>
> Apr 16 11:31:36 sbh16 MailScanner[7964]: Virus and Content Scanning: Starting
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Deleted 30 messages from processing-database
> Apr 16 11:31:37 sbh16 MailScanner[7964]: New Batch: Found 127 messages waiting
> Apr 16 11:31:37 sbh16 MailScanner[7964]: New Batch: Scanning 30 messages, 120892 bytes
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 336A36903ED.24583 to D3FD66903AC
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: F11D7690417.9E54F to 65D8D6903AE
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 450B56903F1.D70D6 to 0A0906903B2
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 6C3AE690430.E51CA to 9642C6903B3
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 48F2F6903F2.3661F to 763816903B7
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: B42FD69040A.B5493 to B44DB6903B9
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 97480690403.80930 to E531F6903BA
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 6666169042F.4E47D to 6D3B26903BB
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: A0781690434.072D5 to 6F9556903BF
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 9B54E690404.C24A1 to DC0DD6903C0
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: C037F69043C.7D493 to DF5256903C1
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 105AC6903E7.3368A to CFF456903C2
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 6CCA96903FA.E31E6 to D42B56903C5
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: C420769043D.67C45 to EE1286903C6
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 7BF02690431.56984 to 913556903C7
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 20FB66903EA.01436 to 3DAE76903C9
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: CE501690411.94E55 to 443816903CB
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 934F7690402.52087 to 598256903CC
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: B0296690409.48B7D to E8B486903CD
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 0979369041A.F3A1A to B1BDA6903D0
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: A37CF690406.A02ED to 437206903D1
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: EB661690447.1DF7F to D1FA66903D2
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: DCE6F690414.0BCEE to 143F96903D5
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 877AD690400.9AAE0 to B490D6903D7
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 588BB6903F6.254CC to 68A556903D9
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 4726D690427.649C5 to CCEC16903DB
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 28CAA690420.AD4D2 to 339C36903DF
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 64E3C6903F8.658D6 to 407EF6903E1
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: 9FA4A690405.B9B10 to 902AF6903E5
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Requeue: D2577690412.52519 to 4747F6903BC
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Unscanned: Delivered 30 messages
> Apr 16 11:31:37 sbh16 MailScanner[7964]: Virus and Content Scanning: Starting
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Deleted 30 messages from processing-database
> Apr 16 11:31:38 sbh16 MailScanner[7964]: New Batch: Found 97 messages waiting
> Apr 16 11:31:38 sbh16 MailScanner[7964]: New Batch: Scanning 30 messages, 121158 bytes
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: BC4D069043B.777A3 to 623046903AA
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 05810690419.33A51 to E218A6903AB
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: B47F8690439.464C1 to C41B46903AC
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 389EA690424.7DCF3 to 4A0556903AD
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 816C3690432.2BE4B to 83A936903B2
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: ACA46690437.BD2A0 to EEBCC6903B3
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 4EFFC690429.BD09A to AC4F26903B4
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: B0971690438.876AB to B09C26903B7
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: DFCA6690444.79EE7 to 6D3936903B8
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 24B1469041F.A45EF to C3DD86903B9
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 40A71690426.66783 to 2F7306903BA
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 52E1969042A.BD93F to 616366903BC
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: EF5F6690448.44D36 to 47D456903C2
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: E39AD690445.8037C to 36FE26903C5
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 9706C690433.A3336 to CDD416903C6
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 30AB7690422.7F6E5 to 004716903C8
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: CC24969043F.3433C to C6D216903C9
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 3C9F8690425.4A529 to 591C26903CA
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: A854E690436.D6E4F to 280D56903CB
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 5E94569042D.39B6A to EEB5E6903CE
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: C826E69043E.3B1F7 to 3AECC6903D2
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: F33BD690449.C869C to BD3F869038D
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 56D6869042B.0F0E1 to 2B4C06903D4
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 6279669042E.63D5C to 871B36903D7
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 1559D69041D.13C96 to 02CB06903D8
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: D3F63690441.21521 to D2D026903D9
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 2CCD7690421.699BE to 265C96903DA
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: 4B044690428.9C9EF to 681466903DC
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: D7E39690442.94286 to 6F22C6903DD
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Requeue: A461E690435.80B0E to C1D686903DF
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Unscanned: Delivered 30 messages
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Virus and Content Scanning: Starting
> Apr 16 11:31:38 sbh16 MailScanner[7964]: Deleted 30 messages from processing-database
> Apr 16 11:31:39 sbh16 MailScanner[7964]: New Batch: Found 67 messages waiting
> Apr 16 11:31:39 sbh16 MailScanner[7964]: New Batch: Scanning 30 messages, 121168 bytes
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 0B0C769044C.14448 to 2CC006903AA
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 5AAB369042C.94441 to 8D48E6903AE
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 64BFE690461.4313B to B57F96903B0
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: E7800690446.A0125 to 419646903B1
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 25F47690453.7561B to 2BF606903B3
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: E0DB169047F.7F471 to 702156903B4
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 1E7A9690451.141ED to 664DC6903BA
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: BC1F3690476.8CE9A to 8850E6903BB
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 011A3690418.4F8F3 to E13106903BC
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 0D4E769041B.144E1 to D3F4F6903BD
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: B867569043A.D005A to 548CA6903BF
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: CC76869047A.B63D4 to 74D3C6903C0
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 743B6690465.580B9 to EF2446903C1
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 34979690423.56858 to 1F3606903C6
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 1C40069041E.B9551 to 0E64A6903C7
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: A46B6690471.0AA1E to F205F6903C8
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: DBC6E690443.CC0B9 to DE1416903CA
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 440B569045B.0781A to 4A4616903CB
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: D05AF69047B.3A5A2 to 843436903CD
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 29C09690454.99468 to 326F16903CE
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 83DE0690469.ECFA9 to 11F866903D0
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 9C42F69046F.B95A7 to 864ED6903D1
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 4C16969045C.35DE5 to 556916903D2
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 1AA3B690450.8FE7A to EE0636903D3
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: AAB35690473.92692 to 833A46903D5
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: EC922690482.B272D to B40A86903D7
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: C8871690479.E5DEB to EC2CA6903DD
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: D01F9690440.914DD to 3CB086903D8
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 114DE69041C.7109B to 397796903E1
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Requeue: 16DE969044F.1E99E to D16776903E2
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Unscanned: Delivered 30 messages
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Virus and Content Scanning: Starting
> Apr 16 11:31:39 sbh16 MailScanner[7964]: Deleted 30 messages from processing-database
>
> You will see that each batch starts with "New Batch: Scanning 30
> messages", Requeues 30 messages and ends with "Unscanned: Delivered 30
> messages" and "Deleted 30 messages from processing-database" yet in the
> first and third batches, one of the messages wasn't deleted from the
> database.
>
>
>    

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.