CentOS - Mar 2015 - Apparent bug in logwatch's reporting of number of email by sendmail

On 03/13/2015 01:06 PM, Blake Hudson wrote:
> ken wrote on 3/13/2015 11:36 AM:
>> # rpm -q sendmail logwatch
>> sendmail-8.13.8-8.1.el5_7
>> logwatch-7.3-10.el5
>>
>> One host sends just one email per day, the daily logwatch report.
>> Here's /var/log/maillog entries from yesterday (hostnames are
changed
>> to make designations in this conversation more intuitive):
>>
>> Mar 12 04:02:18 srchost sendmail[27151]: t2C82Bjr027151: from=root,
>> size=2485, class=0, nrcpts=1,
>> msgid=<201503120802.t2C82Bjr027151 at localhost.localdomain>,
>> relay=root at localhost
>> Mar 12 04:02:19 srchost sendmail[27383]: t2C82IiB027383:
>> from=<root at localhost.localdomain>, size=2756, class=0,
nrcpts=1,
>> msgid=<201503120802.t2C82Bjr027151 at localhost.localdomain>,
>> proto=ESMTP, daemon=MTA, relay=srchost [127.0.0.1]
>> Mar 12 04:02:19 srchost sendmail[27151]: t2C82Bjr027151:
>> to=recip at dest, ctladdr=root (0/0), delay=00:00:08, xdelay=00:00:01,
>> mailer=relay, pri=32485, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0,
>> stat=Sent (t2C82IiB027383 Message accepted for delivery)
>> Mar 12 04:02:20 srchost sendmail[27385]: t2C82IiB027383:
>> to=<recip at dest.com>, ctladdr=<root at
localhost.localdomain> (0/0),
>> delay=00:00:01, xdelay=00:00:01, mailer=esmtp, pri=122756,
>> relay=dellap.mousecar.net. [192.168.0.26], dsn=2.0.0, stat=Sent
>> (t2C82Jh3016227 Message accepted for delivery)
>> Mar 13 04:02:13 srchost sendmail[30541]: t2D82ATM030541: from=root,
>> size=2589, class=0, nrcpts=1,
>> msgid=<201503130802.t2D82ATM030541 at localhost.localdomain>,
>> relay=root at localhost
>>
>> These four lines describe the sending of just one email.  (The
>> loglevel for sendmail is set at 9, the default.)  I don't know why,
>> but logwatch reports that two emails were sent yesterday. Could it be
>> because there are two distinct msgids?
>> Here's the relevant section of the logwatch report:
>>
>> --------------------- sendmail Begin ------------------------
>>
>>  STATISTICS
>>  ----------
>>
>>  Bytes Transferred:      5241
>>  Messages Processed:     2
>>  Addressed Recipients:   2
>>
>>  ---------------------- sendmail End -------------------------
>>
>> I'd also like to know where/how logwatch is getting the number for
>> "Bytes Transferred"; it doesn't seem to correspond to
anything.
>>
>> So, unless I'm missing something, that's two problems.  Does
anyone
>> see any others...?  or have a plausible explanation for these
>> inconsistencies?
>>
>> tia.
>
> Ken, the bytes transferred looks to be the size of the first two log
> entries (2485 + 2756 = 5241). I'm not sure what logwatch considers
> individual messages in its sendmail stats, but a unique message ID does
> indicate a unique message. I also want to point out that if your
> logwatch is generating an email, this may be counted in the stats also
> (how, I'm not sure). If logwatch is running at 4AM, when these emails
> are being sent, I could also anticipate some problems, depending on the
> timing involved and when log entries are committed to the log. Overall,
> I wouldn't be concerned.
>
> --Blake
My major concern is accuracy.  I mean, there's not much sense in using 
logwatch if what it's telling me is wrong.

The fact that logwatch runs at 4am shouldn't be the problem here, as 
logwatch is culling data from the previous day.  So no conflict there 
(if that's what you were implying).

You're right about the Bytes Transferred number.  "size" is
mentioned
*three* times in maillog.  It's just another curiosity how logwatch 
picked the two numbers that it did.  However it did it, obviously it's 
double-counting, so logwatch is getting that number wrong as well.

> On 13 Mar 2015, at 18:13, ken <gebser at mousecar.com> wrote:
> 
>> On 03/13/2015 01:06 PM, Blake Hudson wrote:
>> ken wrote on 3/13/2015 11:36 AM:
>>> # rpm -q sendmail logwatch
>>> sendmail-8.13.8-8.1.el5_7
>>> logwatch-7.3-10.el5
>>> 
>>> One host sends just one email per day, the daily logwatch report.
>>> Here's /var/log/maillog entries from yesterday (hostnames are
changed
>>> to make designations in this conversation more intuitive):
>>> 
>>> Mar 12 04:02:18 srchost sendmail[27151]: t2C82Bjr027151: from=root,
>>> size=2485, class=0, nrcpts=1,
>>> msgid=<201503120802.t2C82Bjr027151 at localhost.localdomain>,
>>> relay=root at localhost
>>> Mar 12 04:02:19 srchost sendmail[27383]: t2C82IiB027383:
>>> from=<root at localhost.localdomain>, size=2756, class=0,
nrcpts=1,
>>> msgid=<201503120802.t2C82Bjr027151 at localhost.localdomain>,
>>> proto=ESMTP, daemon=MTA, relay=srchost [127.0.0.1]
>>> Mar 12 04:02:19 srchost sendmail[27151]: t2C82Bjr027151:
>>> to=recip at dest, ctladdr=root (0/0), delay=00:00:08,
xdelay=00:00:01,
>>> mailer=relay, pri=32485, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0,
>>> stat=Sent (t2C82IiB027383 Message accepted for delivery)
First email is sent locally to root.
>>> Mar 12 04:02:20 srchost sendmail[27385]: t2C82IiB027383:
>>> to=<recip at dest.com>, ctladdr=<root at
localhost.localdomain> (0/0),
>>> delay=00:00:01, xdelay=00:00:01, mailer=esmtp, pri=122756,
>>> relay=dellap.mousecar.net. [192.168.0.26], dsn=2.0.0, stat=Sent
>>> (t2C82Jh3016227 Message accepted for delivery)
Root I guess forwards through an alias so it resends to target.
>>> 
> 
> My major concern is accuracy.  I mean, there's not much sense in using
logwatch if what it's telling me is wrong.
I'm guessing it simply parses the message sent lines. Whether or not
treating locally delivered emails is correct or not - I'm inclined to think
it is. Either way it would probably be difficult to exclude it - and then you
would never be able to track locally sent emails.

Jason

On 2015-03-13, Jason Woods
<devel at jasonwoods.me.uk> wrote:
>
>> On 13 Mar 2015, at 18:13, ken
>> <gebser at mousecar.com> wrote:
>> 
>>> On 03/13/2015 01:06 PM, Blake Hudson wrote: ken wrote on 3/13/2015
>>> 11:36 AM:
>>>> # rpm -q sendmail logwatch sendmail-8.13.8-8.1.el5_7
>>>> logwatch-7.3-10.el5
>>>> 
>>>> One host sends just one email per day, the daily logwatch
report.
>>>> Here's /var/log/maillog entries from yesterday (hostnames
are
>>>> changed to make designations in this conversation more
intuitive):
>>>> 
>>>> Mar 12 04:02:18 srchost sendmail[27151]: t2C82Bjr027151:
from=root,
>>>> size=2485, class=0, nrcpts=1,
>>>> msgid=<201503120802.t2C82Bjr027151 at
localhost.localdomain>,
>>>> relay=root at localhost Mar 12 04:02:19 srchost
sendmail[27383]:
>>>> t2C82IiB027383:
>>>> from=<root at localhost.localdomain>,
>>>> size=2756, class=0, nrcpts=1,
>>>> msgid=<201503120802.t2C82Bjr027151 at
localhost.localdomain>,
>>>> proto=ESMTP, daemon=MTA, relay=srchost [127.0.0.1] Mar 12
04:02:19
>>>> srchost sendmail[27151]: t2C82Bjr027151: to=recip at dest,
>>>> ctladdr=root (0/0), delay=00:00:08, xdelay=00:00:01,
mailer=relay,
>>>> pri=32485, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0, stat=Sent
>>>> (t2C82IiB027383 Message accepted for delivery)
>
> First email is sent locally to root.
And that email would be the logwatch report itself, but from 24 hours
before.
>
>>>> Mar 12 04:02:20 srchost sendmail[27385]: t2C82IiB027383:
>>>> to=<recip at dest.com>,
ctladdr=<root-bi+AKbBUZKY6gyzm1THtWbp2dZbC/Bob at public.gmane.org> (0/0),
>>>> delay=00:00:01, xdelay=00:00:01, mailer=esmtp, pri=122756,
>>>> relay=dellap.mousecar.net. [192.168.0.26], dsn=2.0.0, stat=Sent
>>>> (t2C82Jh3016227 Message accepted for delivery)
>
> Root I guess forwards through an alias so it resends to target.
That would be my guess too.
>
>>>> 
>> 
>> My major concern is accuracy.  I mean, there's not much sense in
using logwatch if what it's telling me is wrong.
>
> I'm guessing it simply parses the message sent lines. Whether or not
treating locally delivered emails is correct or not - I'm inclined to think
it is. Either way it would probably be difficult to exclude it - and then you
would never be able to track locally sent emails.
>
> Jason

-- 

Liam

On 03/13/2015 02:29 PM, Jason Woods wrote:
>
>> On 13 Mar 2015, at 18:13, ken <gebser at mousecar.com> wrote:
>>
>>> On 03/13/2015 01:06 PM, Blake Hudson wrote: ken wrote on
>>> 3/13/2015 11:36 AM:
>>>> # rpm -q sendmail logwatch sendmail-8.13.8-8.1.el5_7
>>>> logwatch-7.3-10.el5
>>>>
>>>> One host sends just one email per day, the daily logwatch
>>>> report. Here's /var/log/maillog entries from yesterday
>>>> (hostnames are changed to make designations in this
>>>> conversation more intuitive):
>>>>
>>>> Mar 12 04:02:18 srchost sendmail[27151]: t2C82Bjr027151:
>>>> from=root, size=2485, class=0, nrcpts=1,
>>>> msgid=<201503120802.t2C82Bjr027151 at
localhost.localdomain>,
>>>> relay=root at localhost Mar 12 04:02:19 srchost
sendmail[27383]:
>>>> t2C82IiB027383: from=<root at localhost.localdomain>,
size=2756,
>>>> class=0, nrcpts=1,
>>>> msgid=<201503120802.t2C82Bjr027151 at
localhost.localdomain>,
>>>> proto=ESMTP, daemon=MTA, relay=srchost [127.0.0.1] Mar 12
>>>> 04:02:19 srchost sendmail[27151]: t2C82Bjr027151:
>>>> to=recip at dest, ctladdr=root (0/0), delay=00:00:08,
>>>> xdelay=00:00:01, mailer=relay, pri=32485, relay=[127.0.0.1]
>>>> [127.0.0.1], dsn=2.0.0, stat=Sent (t2C82IiB027383 Message
>>>> accepted for delivery)
>
> First email is sent locally to root.
I see that it's sent *from* root.  Where does it say it's sent *to*
root?
>
>>>> Mar 12 04:02:20 srchost sendmail[27385]: t2C82IiB027383:
>>>> to=<recip at dest.com>, ctladdr=<root at
localhost.localdomain>
>>>> (0/0), delay=00:00:01, xdelay=00:00:01, mailer=esmtp,
>>>> pri=122756, relay=dellap.mousecar.net. [192.168.0.26],
>>>> dsn=2.0.0, stat=Sent (t2C82Jh3016227 Message accepted for
>>>> delivery)
>
> Root I guess forwards through an alias so it resends to target.
/etc/logwatch.conf is configured to send to <recip at dest.com>, so no
aliasing and no resending.

>
>>>>
>>
>> My major concern is accuracy.  I mean, there's not much sense in
>> using logwatch if what it's telling me is wrong.
>
> I'm guessing it simply parses the message sent lines. Whether or not
> treating locally delivered emails is correct or not - I'm inclined to
> think it is. Either way it would probably be difficult to exclude it
> - and then you would never be able to track locally sent emails.
>
> Jason
Tracking where/how emails are sent would be done in maillog, not in 
logwatch.

I'd disagree.  If one email is sent, saying two are sent is not correct. 
  If one email is sent with one recipient, the total number of 
recipients is one.  If I hold up two fingers and ask someone how many 
fingers I'm holding up and she says "four", that too is incorrect.

Yes, it might be difficult to machine-parse the maillog, but then the 
software-- here logwatch-- should either be fixed or its data described 
accurately (and hopefully too, meaningfully).  It shouldn't post 
erroneous data.

>>>
>>> --------------------- sendmail Begin ------------------------
>>>
>>>  STATISTICS
>>>  ----------
>>>
>>>  Bytes Transferred:      5241
>>>  Messages Processed:     2
>>>  Addressed Recipients:   2
>>>
>>>  ---------------------- sendmail End -------------------------
>>>
>>> I'd also like to know where/how logwatch is getting the number
for
>>> "Bytes Transferred"; it doesn't seem to correspond to
anything.
>>>
>>> So, unless I'm missing something, that's two problems. 
Does anyone
>>> see any others...?  or have a plausible explanation for these
>>> inconsistencies?
>>>
>>> tia.
>>
>> Ken, the bytes transferred looks to be the size of the first two log
>> entries (2485 + 2756 = 5241). I'm not sure what logwatch considers
>> individual messages in its sendmail stats, but a unique message ID does
>> indicate a unique message. I also want to point out that if your
>> logwatch is generating an email, this may be counted in the stats also
>> (how, I'm not sure). If logwatch is running at 4AM, when these
emails
>> are being sent, I could also anticipate some problems, depending on the
>> timing involved and when log entries are committed to the log. Overall,
>> I wouldn't be concerned.
>>
>> --Blake
>
> My major concern is accuracy.  I mean, there's not much sense in using 
> logwatch if what it's telling me is wrong.
>
> The fact that logwatch runs at 4am shouldn't be the problem here, as 
> logwatch is culling data from the previous day.  So no conflict there 
> (if that's what you were implying).
>
> You're right about the Bytes Transferred number.  "size" is
mentioned
> *three* times in maillog.  It's just another curiosity how logwatch 
> picked the two numbers that it did.  However it did it, obviously it's 
> double-counting, so logwatch is getting that number wrong as well.
>
Based on the day of 'Mar 12', I agree with the bytes transferred. 
Logwatch's sendmail component appears to be using the sendmail queue ID 
(vs the message ID) as an identifier for a unique message. Using this 
identifier, I too count 2 messages (t2C82IiB027383 and t2C82Bjr027151). 
Looking at recipients, I also count two: recip at dest and <recip at
dest.com>.

What criteria to use as a means of identifying a unique message is 
certainly a choice. I can see how some would choose the MUA's message ID 
instead. However, that may be more error prone given that this is not 
guaranteed to be a unique value within a data set. Sendmail's queue ID 
should be unique in a day's data on a single server.

--Blake

On 03/16/2015 11:25 AM, Blake Hudson wrote:
>
>>>>
>>>> --------------------- sendmail Begin ------------------------
>>>>
>>>>  STATISTICS
>>>>  ----------
>>>>
>>>>  Bytes Transferred:      5241
>>>>  Messages Processed:     2
>>>>  Addressed Recipients:   2
>>>>
>>>>  ---------------------- sendmail End -------------------------
>>>>
>>>> I'd also like to know where/how logwatch is getting the
number for
>>>> "Bytes Transferred"; it doesn't seem to
correspond to anything.
>>>>
>>>> So, unless I'm missing something, that's two problems. 
Does anyone
>>>> see any others...?  or have a plausible explanation for these
>>>> inconsistencies?
>>>>
>>>> tia.
>>>
>>> Ken, the bytes transferred looks to be the size of the first two
log
>>> entries (2485 + 2756 = 5241). I'm not sure what logwatch
considers
>>> individual messages in its sendmail stats, but a unique message ID
does
>>> indicate a unique message. I also want to point out that if your
>>> logwatch is generating an email, this may be counted in the stats
also
>>> (how, I'm not sure). If logwatch is running at 4AM, when these
emails
>>> are being sent, I could also anticipate some problems, depending on
the
>>> timing involved and when log entries are committed to the log.
Overall,
>>> I wouldn't be concerned.
>>>
>>> --Blake
>>
>> My major concern is accuracy.  I mean, there's not much sense in
using
>> logwatch if what it's telling me is wrong.
>>
>> The fact that logwatch runs at 4am shouldn't be the problem here,
as
>> logwatch is culling data from the previous day.  So no conflict there
>> (if that's what you were implying).
>>
>> You're right about the Bytes Transferred number.  "size"
is mentioned
>> *three* times in maillog.  It's just another curiosity how logwatch
>> picked the two numbers that it did.  However it did it, obviously
it's
>> double-counting, so logwatch is getting that number wrong as well.
>>
> Based on the day of 'Mar 12', I agree with the bytes transferred.
> Logwatch's sendmail component appears to be using the sendmail queue ID
> (vs the message ID) as an identifier for a unique message. Using this
> identifier, I too count 2 messages (t2C82IiB027383 and t2C82Bjr027151).
> Looking at recipients, I also count two: recip at dest and <recip at
dest.com>.
If someone knew absolutely nothing about email, then yes, recip at dest and 
<recip at dest.com> might be seen as two recipients.  But sendmail, an 
inert body of code, knows that those are two ways of addressing one and 
the same recipient and indeed sends me just one email, not one to 
recip at dest and another to recip at dest.com.  Logwatch, however, lacks the 
sophistication to understand that these are simply two ways of 
*addressing*, or *referring* to, one and the same recipient.

Similarly, simply because there are two different numerical identifiers, 
both *referring* to one and the same email doesn't mean there are two 
emails.  If there were a third number referring to that one email would 
we then magically have three emails?  I'm wondering, then, what would 
happen in logwatch if an administrator changed sendmail's loglevel to 
something other than the default...?

>
> What criteria to use as a means of identifying a unique message is
> certainly a choice. I can see how some would choose the MUA's message
ID
> instead. However, that may be more error prone given that this is not
> guaranteed to be a unique value within a data set. Sendmail's queue ID
> should be unique in a day's data on a single server.
>
> --Blake
I'll leave the criteria selection as well as the logic to interpret that 
up to the logwatch developer(s).  Perhaps sendmail's logging would need 
to be made less ambiguous for logwatch (and other possible diagnostic 
programs).  Whatever fixes the problem is fine with me.

Blake, thanks for playing devil's advocate and pointing out the probable 
sources of unwarranted conflation.  At first I was a bit unsure, but 
after this conversation we can with certainty conclude that, yes, this 
is a bug.