INN 2.4.3 candidate news.notice parsing nit (resent)

[Jeffrey M. Vinocur]

I'm resending this from a couple weeks ago, since the mailing list  
seems to have eaten it...



Yesterday I installed 2.4.3 (in place of the 20050716 CVS  
prerelease), and I seem to have picked up some sort of trouble  
parsing news.notice entries that were created before the change.  I  
guess in some sense this is a downgrade, and so as long as 2.4.3 can  
parse its own logs, we should be fine?

[ I figure out the problem below, so don't waste too much time  
staring at the log entries ]



When running CURRENT (albeit an old CURRENT), news.daily was always  
spouting off about this stuff (some duplicates edited out for brevity):

   Unknown entries from news log file:
   First 50 / 326 lines (15.3%)
   Dec 28 04:00:08 puck innd: ctlinnd command E
   Dec 28 04:00:08 puck innd: ctlinnd command h:Flushing log and  
syslog files
   Dec 28 04:02:48 puck innd: CNFS: CNFSflushallheads: flushing GENERL2
   Dec 28 04:07:48 puck innd: CNFS: CNFSflushallheads: flushing CONTRL1
   Dec 28 04:36:07 puck innd: ctlinnd command L:/sysroot/var/log/news/ 
expire.lowmark
   Dec 28 04:36:53 puck innd: ctlinnd command s
   Dec 28 04:36:54 puck innd: ctlinnd command z:Expiring process 10952
   Dec 28 04:47:52 puck innd: CNFS: CNFSflushallheads: flushing GENERL2
   Dec 28 04:52:53 puck innd: CNFS: CNFSflushallheads: flushing CONTRL1
   [ ... much more of the same ... ]

I never had time to track down what that was all about, but it was  
consistently ~350 lines unrecognized.  After installing 2.4.3 (around  
10:30 AM yesterday), INN ran for the rest of the day and then this  
morning's news.daily reported all of the same stuff plus a bunch of  
additional entries:

   Unknown entries from news log file:
   First 50 / 1176 lines (4.3%)
   Dec 29 04:00:08 puck innd: ctlinnd command E
   Dec 29 04:00:08 puck innd: ctlinnd command h:Flushing log and  
syslog files
   Dec 29 04:00:10 puck innd: nrc-news.nrc.ca:102 closed seconds 8  
accepted 0 refused 32 rejected 14 duplicate 14 accepted size 0  
duplicate size 28229 rejected size 0
   Dec 29 04:00:41 puck innd: news.mbo.net:49 closed seconds 78  
accepted 0 refused 0 rejected 0 duplicate 0 accepted size 0 duplicate  
size 0 rejected size 0
   Dec 29 04:00:41 puck innd: news.mbo.net:52 closed seconds 78  
accepted 2 refused 20 rejected 1 duplicate 1 accepted size 4241  
duplicate size 1360 rejected size 0
   Dec 29 04:14:24 puck innd: CNFS: CNFSflushallheads: flushing GENERL2
   Dec 29 04:15:03 puck innd: news.greenie.muc.de:65 closed seconds 0  
accepted 0 refused 1 rejected 0 duplicate 0 accepted size 0 duplicate  
size 0 rejected size 0
   [ ... much more of the same ... ]

having trouble with status lines from many different peers.  And the  
cumulative totals in other parts of news.daily don't seem to quite  
add up adequately.

Careful comparison of the lines flagged in news.daily with  
yesterday's news.notice reveals that it's only the "closed" type innd  
entries that are trouble, and...oh!


Okay, the problem is that at some point we added the "rejected size"  
field to the end of those entries!

It's probably not necessary to backport the actual patch for log  
parsing, but perhaps we should make a note that on the first day  
2.4.3 is installed over a more recent 2.5 prerelease, there may be  
lots of garbage in the news.daily report?


-- 
Jeffrey M. Vinocur
jeff at litech.org