Bug 702114 - Add way to drop timestamps from log output
Summary: Add way to drop timestamps from log output
Keywords:
Status: CLOSED UPSTREAM
Alias: None
Product: Virtualization Tools
Classification: Community
Component: libvirt
Version: unspecified
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Libvirt Maintainers
QA Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-05-04 19:24 UTC by Guido Günther
Modified: 2011-10-14 20:44 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2011-10-14 20:44:00 UTC
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Debian BTS 625288 0 None None None Never

Description Guido Günther 2011-05-04 19:24:40 UTC
Citing from the Debian bugreport:

I run logcheck with syslog-summary enabled.  That allows me to get ONE
line like this, indicating the number of duplicate (in this case 10):

    10 stomp dovecot: IMAP(russm): stat(/var/mail/lists/.managers/tmp) failed: Permission denied (euid=1033(russm) egid=1033(russm) missing +x perm: /var/mail/lists/.managers)

However, libvirtd includes its own timestamps in its syslog messages, which completely ruins this:

    1 theta libvirtd: 15:33:46.516: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012
    1 theta libvirtd: 15:33:46.523: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012
    1 theta libvirtd: 15:33:46.530: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012
    1 theta libvirtd: 15:33:46.537: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012
    1 theta libvirtd: 15:33:46.544: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012
    1 theta libvirtd: 15:33:46.551: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012
    1 theta libvirtd: 15:33:46.558: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012
    1 theta libvirtd: 15:33:46.565: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012
    1 theta libvirtd: 15:33:46.572: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012
    1 theta libvirtd: 15:33:46.579: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012
    1 theta libvirtd: 15:33:46.586: error : checkType:2495 : remoteReadConfigFile: /etc/libvirt/libvirtd.conf: unix_sock_group: invalid type: got long; expected string#012

Please remove, or at least make optional, these timestamps.  This is analogous to these smb.conf options:

    [global]
    # Without these, logserv's syslog-summary(1) fails to merge
    # identical smb log entries in logcheck emails.
       debug prefix timestamp = no
       debug timestamp = no

This imho makes a lot of sense.

Comment 1 Daniel Veillard 2011-05-05 15:03:57 UTC
Starting with 0.9.0 libvirtd doesn't log to syslog by default
but to /var/log/libvirt/libvirtd.log , then that file is logrotated.
Having the full timestamp can be crucial when debugging some issues.
We could optionally turn it off, but I wonder if the new behaviour isn't
a better fix to the problem.

Daniel

Comment 2 Dave Allan 2011-05-05 15:12:39 UTC
DV, IIUC, the problem is that the timestamps are messing up logcheck's ability to coalesce the log lines, and where the log goes isn't going to affect that.  Guido, does logcheck have some regex-like facility for ignoring parts of the lines it's coalescing?

Also, would you mind taking the discussion to the mailing list, and provide a PoC patch if you're able to?

Dave

Comment 3 Guido Günther 2011-05-05 16:02:07 UTC
logcheck invokes syslog-summary which has a hardcoded pattern for matching dates:

  re.compile(r"^(Jan|Feb|Mar|Apr|May|Jun|Jul|Aug|Sep|Oct|Nov|Dec) [ 0-9][0-9] [ 0-9][0-9]:[0-9][0-9]:[0-9][0-9] "),
        re.compile(r"^(Mon|Tue|Wed|Thu|Fri|Sat|Sun) (Jan|Feb|Mar|Apr|May|Jun|Jul|Aug|Sep|Oct|Nov|Dec) [ 0-9][0-9][0-9][0-9]:[0-9][0-9] "),
        re.compile(r"^(Mon|Tue|Wed|Thu|Fri|Sat|Sun) (Jan|Feb|Mar|Apr|May|Jun|Jul|Aug|Sep|Oct|Nov|Dec) [ 0-9][0-9][0-9][0-9]:[0-9][0-9]:[0-9][0-9] "),

The issue is that when logging through syslog the second timestamp isn't catched by that. Now with a separate syslog the timestamp used by libvirt itself doesn't match this either. 

People might want to continue to log through syslog to use syslog-summary, etc. in that case disabling the timestamp would make sense.

I'll won't be able to come up with a patch nearterm that's why I filed the bug. I'll restart the discussion on the ML once I have time to work on this. 

Thanks for your comments.

Comment 4 Eric Blake 2011-05-05 16:11:13 UTC
Does that mean libvirt needs to change its timestamp output to match the hardcoded expectations of syslog-summary?  And/or, should we spawn a bug against syslog to improve the regex parser to accept libvirt's format?

Comment 5 Jiri Denemark 2011-05-06 06:13:02 UTC
This means that we should not include timestamps in the log message when logging to syslog, syslog deamon will prefix the message with it's own timestamp anyway. Including them in libvirtd.log or any other file is fine and desirable.

Comment 6 Guido Günther 2011-05-07 16:48:54 UTC
> This means that we should not include timestamps in the log message when
> logging to syslog, syslog deamon will prefix the message with it's own
> timestamp anyway. 

Having exactly that would be great!

> Including them in libvirtd.log or any other file is fine and
desirable.

We might want use a format similar to syslog though to help parsers like logcheck with syslog-summary along.

Comment 7 Jiri Denemark 2011-10-14 20:44:00 UTC
This is now fixed upstream by

commit 2a449549c1db0befef8a807bfe967a04af8b529b
Author: Jiri Denemark <jdenemar>
Date:   Wed Sep 28 15:20:07 2011 +0200

    logging: Do not log timestamp through syslog
    
    Syslog puts the timestamp to every message anyway so this removes
    redundant data.


Note You need to log in before you can comment on or make changes to this bug.