Found nn messages in the processing-messages database

Fri Apr 17 03:57:44 IST 2009

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.

-- 
Mark Sapiro mark at msapiro net       The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan