Bug 393 - Add date and cross reference (msgid) to -D (debug output)
Summary: Add date and cross reference (msgid) to -D (debug output)
Status: RESOLVED DUPLICATE of bug 399
Alias: None
Product: Spamassassin
Classification: Unclassified
Component: spamassassin (show other bugs)
Version: 2.20
Hardware: All All
: P2 enhancement
Target Milestone: ---
Assignee: SpamAssassin Developer Mailing List
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2002-06-04 10:11 UTC by Harry Putnam
Modified: 2002-06-11 15:48 UTC (History)
0 users



Attachment Type Modified Status Actions Submitter/CLA Status

Note You need to log in before you can comment on or make changes to this bug.
Description Harry Putnam 2002-06-04 10:11:29 UTC
Make the -D (debug) output more usefull by datestamping and grabbing the msgid 
from the message at hand.  Hopefully this would facilitate going through log
output with a msgid in hand to see how spammassasin reported that message.
Comment 1 Marc MERLIN 2002-06-04 11:05:03 UTC
You're in luck, I should propose a patch tonight that does this and more
Comment 2 Craig Hughes 2002-06-04 22:11:07 UTC
I agree on msgid, disagree on timestamp.  I think better would be to change spamd to intercept 
warn() with a #SIG{__WARN__} handler and redirect Mail::SpamAssassin::dbg() calls to syslog 
which will then provide the date/time stamp.
Comment 3 Harry Putnam 2002-06-05 06:44:46 UTC
I disagree with:
Craigs comment - "I think better would be to change spamd to intercept 
warn() with a #SIG{__WARN__} handler and redirect Mail::SpamAssassin::dbg()
calls to syslog which will then provide the date/time stamp."

Yes, if it goes to syslog then no need of timestamp, but one of the beauties
spamd is that by leaving out the -d (daemonize) and using -D debug, the output
can be redirected in any normal shell rule sort of way.  Always nice to have a 
`clean' log and not involve syslog if so desired.  Especially when involved in 
heavy debugging.
So, I guess the best would be to have no timestamp on syslog redirect but to
allow time stamping at user request (an additional (-t?) flag, that is inactive
if -d is engaged.
Comment 4 Matt Sergeant 2002-06-05 06:55:44 UTC
Subject: Re: [SAdev]  Add date and cross reference (msgid) to -D
 (debug output)

bugzilla-daemon@hughes-family.org wrote:
> http://www.hughes-family.org/bugzilla/show_bug.cgi?id=393
> 
> 
> 
> 
> 
> ------- Additional Comments From reader@newsguy.com  2002-06-05 06:44 -------
> I disagree with:
> Craigs comment - "I think better would be to change spamd to intercept 
> warn() with a #SIG{__WARN__} handler and redirect Mail::SpamAssassin::dbg()
> calls to syslog which will then provide the date/time stamp."
> 
> Yes, if it goes to syslog then no need of timestamp, but one of the beauties
> spamd is that by leaving out the -d (daemonize) and using -D debug, the output
> can be redirected in any normal shell rule sort of way.  Always nice to have a 
> `clean' log and not involve syslog if so desired.  Especially when involved in 
> heavy debugging.
> So, I guess the best would be to have no timestamp on syslog redirect but to
> allow time stamping at user request (an additional (-t?) flag, that is inactive
> if -d is engaged.

Personally I think we should use Log::Dispatch::Config (and use LDC's 
alternate config system to pick up the config from SpamAssassin config 
files). It's incredibly flexible in it's logging, and I can attest to 
it's reliability.

Matt.

Comment 5 Matt Sergeant 2002-06-05 06:56:14 UTC
Subject: Re: [SAdev]  Add date and cross reference (msgid) to -D
 (debug output)

bugzilla-daemon@hughes-family.org wrote:
> http://www.hughes-family.org/bugzilla/show_bug.cgi?id=393
> 
> 
> 
> 
> 
> ------- Additional Comments From reader@newsguy.com  2002-06-05 06:44 -------
> I disagree with:
> Craigs comment - "I think better would be to change spamd to intercept 
> warn() with a #SIG{__WARN__} handler and redirect Mail::SpamAssassin::dbg()
> calls to syslog which will then provide the date/time stamp."
> 
> Yes, if it goes to syslog then no need of timestamp, but one of the beauties
> spamd is that by leaving out the -d (daemonize) and using -D debug, the output
> can be redirected in any normal shell rule sort of way.  Always nice to have a 
> `clean' log and not involve syslog if so desired.  Especially when involved in 
> heavy debugging.
> So, I guess the best would be to have no timestamp on syslog redirect but to
> allow time stamping at user request (an additional (-t?) flag, that is inactive
> if -d is engaged.

Personally I think we should use Log::Dispatch::Config (and use LDC's 
alternate config system to pick up the config from SpamAssassin config 
files). It's incredibly flexible in it's logging, and I can attest to 
it's reliability.

Matt.


_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

_______________________________________________
Spamassassin-devel mailing list
Spamassassin-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/spamassassin-devel

Comment 6 Craig Hughes 2002-06-05 15:14:49 UTC
Checked in a $SIG{__WARN__} handler one-liner for spamd.  Leaving this bug open pending me 
taking a look at Log::Dispatch::Config
Comment 7 Craig Hughes 2002-06-05 18:11:13 UTC
I actually realized after adding the WARN handler that syslog only give second-level time 
resolution, so I think using the timestamp stuff that was in that massive 4-thing patch submitted 
yesterday on bug #399 might be useful.  I'll see about making use of that.
Comment 8 Craig Hughes 2002-06-10 03:25:11 UTC
Ok, so bug #399 is now done.

*** This bug has been marked as a duplicate of 399 ***
Comment 9 Harry Putnam 2002-06-10 07:15:19 UTC
Subject: Re:  Add date and cross reference (msgid) to -D (debug
 output)

bugzilla-daemon@hughes-family.org writes:

> http://www.hughes-family.org/bugzilla/show_bug.cgi?id=393
>
> craig@hughes-family.org changed:
>
>            What    |Removed                     |Added
> ----------------------------------------------------------------------------
>              Status|NEW                         |RESOLVED
>          Resolution|                            |DUPLICATE
>
>
>
> ------- Additional Comments From craig@hughes-family.org  2002-06-10 03:25 -------
> Ok, so bug #399 is now done.
>
> *** This bug has been marked as a duplicate of 399 ***
>

Sorry Folks but the confusing setup at bugzilla wouldn't allow me to
insert this further comment.  I inserted `393 in a query and then
tried to insert comments in the comments box. It  gives an error:
    Only the owner or submitter of the bug, or a sufficiently empowered
   user, may make that change to the short_desc field. 
    Old value:  Fixed RBLs / RBL timeouts / Time logging / Debug framework
    New value:  Fixed RBLs / RBL timeouts / Time logging/ Debug framework

Somewhat confusing since I made no attempt to change anything and the
alleged change is not a change at all anyway.

My further comment is:
As the originator of bug 393, I wasn't able to tell what 399 is supposed to do
from reading the 399 chain of events and description.

Will the message id of a processed message now be part of the DEBUG output?
Will debug output (outside of syslog) have a time stamp?

Comment 10 Craig Hughes 2002-06-11 09:41:31 UTC
Subject: Re: [SAdev] Re:  Add date and cross reference (msgid) to
 -D (debug output)

Yes, 399 is a full superset of 393, so MsgID and timestamp are now logged, if 
you use the -D flag to either spamd or spamassasin, or if you instantiate the 
scanner object with 'debug' => 1

Comment 11 Marc MERLIN 2002-06-11 14:42:38 UTC
Ok, now that my patch has been included (I wasn't sure if all of it would be, or
what modifications would be applied), I can offer a bit more info:
Technically this is a different request than what I did in 399.
My timelog function allows you to log the major functions of SA and see how long
they took. This all gets saved to a file that contains the message-ID of the
message that was processed.
However, my patch does not redirect dbg calls to send them to timelog.

That said, if you feel you want to run SA in dbg mode and production, you could
trivially edit one line in the dbg function and send the prints from dbg to the
timelog function.
It will also conveniently save the dbg info to a different file for each
incoming message.

We *could* make this an option if Craig and others think it might be useful to
others, or you could simply edit your source to send the dbg print to timelog.

Would that be good enough, or do you think SA should support this as an option
that you can turn on from local.cf?

I have to submit a small folloup patch on 399 for the cf files so that the rules
can now take advantage of the new framework that was just introduced
(Craig, I'll try to send a patch tonight. Bear with me, I just got laser eye
surgery, so I'm not really supposed to be using a computer at all right now :)
Comment 12 Harry Putnam 2002-06-11 22:18:36 UTC
Subject: Re:  Add date and cross reference (msgid) to -D (debug
 output)

bugzilla-daemon@hughes-family.org writes:

> http://www.hughes-family.org/bugzilla/show_bug.cgi?id393

> ------- Additional Comments From craig@hughes-family.org  2002-06-11 09:41 -------
> Subject: Re: [SAdev] Re:  Add date and cross reference (msgid) to
>  -D (debug output)
>
> Yes, 399 is a full superset of 393, so MsgID and timestamp are now logged, if 
> you use the -D flag to either spamd or spamassasin, or if you instantiate the 
> scanner object with 'debug' => 1

Using cvs of yesterday showing version 2.21 and running spamd like
this:
  /usr/bin/spamd -D -L -S >> /var/log/spamd_debug.log 2>&1 &

I see no indication of a timestamp or any record of a message-id
in spamd_debug.log

Several people have said that 399 includes 393, but I don't see the
things that were presented in 393 bug report or its later discussion.
I see no mention of a timestamp switch in the most recent man page.
(That I have)

Specifically: A switch to turn on timestamping for the above kind of
              redirect.
              Logging message-id as part of -D (debug) output

Here is some example output of the above redirect:
(wrapped for mail)
[...]
  Possible unintended interpolation of @pop in string at (eval 20) line
  503, <STDIN> line 77.  Failed to run header SpamAssassin tests,
  skipping some: Global symbol "@pop" requires explicit package name at
  (eval 20) line 503, <STDIN> line 77.
[...]

I suspect this is related to local.cf entry I made:
  header From_Pop From =~ /@pop\./
  describe From_pop From: header contains @pop\. in address
  score From_Pop 1.5

Maybe not, but I can't really tell much from the debug output.
I've searched the debug output of several messages. They  begin
with something like:

   logmsg: connection from localhost [ 127.0.0.1 ] at port 42157

Then some 72 lines of ouput, ending with:

   logmsg: clean message (1.4/5.0) for reader:500 in 0 seconds, 3710
   bytes.

I'm probably blind, but I'll be damned if I can find a message-id
anywhere in between.

And as I mentioned that is with a cvs version of yesterday around noon.
But just to make sure it isn't just that I haven't got the recent
changes.  Let me check out a version now and try it out.....

cd /usr/local/src/spamassassin
make distclean
cvs update
make
make test (all tests passed)
make install 

service spamassassin restart

After retrieving several runs of mail I see no evidence in the log
ouput of timestamping or message id.


Comment 13 Marc MERLIN 2002-06-11 23:48:53 UTC
You're not blind, the current CVS code does not add mesgid or a timestamp to debug
messages, see my previous comment.