Bug 6231 - Care for adding timestamps when logging to stderr?
Summary: Care for adding timestamps when logging to stderr?
Status: RESOLVED FIXED
Alias: None
Product: Spamassassin
Classification: Unclassified
Component: Libraries (show other bugs)
Version: 3.3.0
Hardware: All All
: P5 enhancement
Target Milestone: 3.3.0
Assignee: SpamAssassin Developer Mailing List
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2009-10-30 09:57 UTC by Mark Martinec
Modified: 2010-01-31 11:45 UTC (History)
3 users (show)


Attachment Type Modified Status Actions Submitter/CLA Status
suggested patch application/octet-stream None Mark Martinec [HasCLA]
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Mark Martinec 2009-10-30 09:57:03 UTC 
Created attachment 4563 [details]
suggested patch

When troubleshooting timing issues it comes handy if the logged debug messages
carry timestamps when logging goes to stderr, such as with 'spamassassin -D':

Oct 30 17:44:52.579 [40776] dbg: pyzor: opening pipe:
  /usr/local/bin/pyzor --homedir /var/amavis/home/.pyzor check ...
Oct 30 17:44:52.586 [40791] dbg: util: setuid: ruid=110 euid=110
Oct 30 17:44:52.663 [40776] dbg: pyzor: [40791] finished successfully
Oct 30 17:44:52.663 [40776] dbg: pyzor: got response: public.pyzor.org:24441...

Attached is a suggested patch to Logger/Stderr.pm.

Yes? No? Too intrusive? Needs yet another configuration option???
Comment 1 Justin Mason 2009-10-30 14:31:30 UTC 
actually, I'm fine with this.  It's a big change, but useful, and an x.0 release is the right time to do it.
Comment 2 Mark Martinec 2009-10-30 17:15:02 UTC 
Bug 6231: add timestamps when logging on stderr
Sending        lib/Mail/SpamAssassin/Logger/Stderr.pm
Committed revision 831492.
Comment 3 Mark Martinec 2009-10-30 17:37:30 UTC 
Closing. Please re-open if somebody does not like the idea.
Comment 4 Adam Katz 2009-10-31 14:42:21 UTC 
FYI, there was enough demand on IRC that I wrote a workaround solution for this.  Perhaps helpful for anybody on a pre-3.3.0 version or even with another program altogether (since it actually has nothing to do with SpamAssassin ... I use it regularly with ping for example).

http://khopesh.com/Anti-spam#SA_utility_scripts

timed-debug (previously called sa-timed-debug) will print the date to the console as you debug something live.

Examples:

# run SpamAssassin with debug, printing the time every third of a second
timed-debug -0.33 spamassassin -D

# run ping with the time and host name every 15 seconds (better wrapping on 80-col)
timed-debug -15 ping -n google.com

I run these in aliases so i can just say "pin google.com" or "sa-timed-debug <msg.eml" ... see the --help output.
Comment 5 Mark Martinec 2009-10-31 16:42:56 UTC 
> FYI, there was enough demand on IRC that I wrote a workaround solution for
> this.  Perhaps helpful for anybody on a pre-3.3.0 version or even with another
> program altogether (since it actually has nothing to do with SpamAssassin ... 

For completeness, here was mine, published on the SA user list:

  http://marc.info/?l=spamassassin-users&m=123819766930870
Comment 6 kim 2010-01-31 11:45:11 UTC 
It is kind of a problem when you run spamd under daemontools using an alternative logger (like multilog or logger). 

This results in double timestamps in the logs:

2010-01-31T20:37:00.908249+01:00 mail spamd: Jan 31 20:37:00.908 [1158] info: spamd: server started on port 783/tcp (running version 3.3.0)
2010-01-31T20:37:00.908289+01:00 mail spamd: Jan 31 20:37:00.908 [1158] info: spamd: server pid: 1158
2010-01-31T20:37:00.909964+01:00 mail spamd: Jan 31 20:37:00.910 [1158] info: spamd: server successfully spawned child process, pid 1162
2010-01-31T20:37:00.912102+01:00 mail spamd: Jan 31 20:37:00.912 [1158] info: spamd: server successfully spawned child process, pid 1163
2010-01-31T20:37:00.913236+01:00 mail spamd: Jan 31 20:37:00.913 [1158] info: prefork: child states: IS
2010-01-31T20:37:00.914073+01:00 mail spamd: Jan 31 20:37:00.914 [1158] info: prefork: child states: II

Maybe the timestamps could be confined to debug mode only?

This is the command-line I uses via daemontools (/service/run file):  
spamd  --max-children 10 --nouser-config --username=clamav --syslog stderr 2>&1

SpamAssassin Server version 3.3.0
  running on Perl 5.10.0
  with zlib support (Compress::Zlib 2.024)

Kind regards

Kim