Bug 640202

libvirt logs should be improved in order to allow proper analysis of daily issues. 
I would like to points for the following cases: 

1) threading - in order to tail a problem, one needs some kind of 'tagging' for single session (thread), in such, it will help us follow the issue from the beginning, till the end, and pin point the scenario\issue. 

2) failed actions does not refer to faulty domains (vm), and such, when we see an error, we cannot refer it to the correspondence domain, which makes debugging problem problematic. 

examples: 


10:38:19.638: error : qemudDomainBlockStats:9738 : Requested operation is not valid: domain is not running 

that explains the above for both vm identification and threading.

It isn't practical to include the VM name/uuid/etc in every error message. We do however generate a log line at the entry to each public API call. This could be made to include the VM uuid/name. If we included a thread ID in every log line, you could then correlate the error log message, with the API entry point log message and identify the VM

comment 3's solution seems workable, isn't it, Haim?

btw, 

debug : virDomainLookupByUUID:2045 : conn=0x7f9eb0003300, uuid=<9F><FE>(<B6>a4K^^<88>^D^Q<85><F4><9C>Co

should better log the ASCII form of the domain uuid.

(In reply to comment #4)
> comment 3's solution seems workable, isn't it, Haim?
> 
> btw, 
> 
> debug : virDomainLookupByUUID:2045 : conn=0x7f9eb0003300,
> uuid=<9F><FE>(<B6>a4K^^<88>^D^Q<85><F4><9C>Co
> 
> should better log the ASCII form of the domain uuid.

sounds good.

One part of the fix is posted, to include a thread ID.

http://www.redhat.com/archives/libvir-list/2010-November/msg00947.html

More to come...

patch got pushed upstream: a98d8f0d274372d49915bf82dd09c82b156e5200

tried the following things , but I'm not sure they are correct to get any conclusion to verify this bug :

1. set value of "log_level" in "/etc/libvirt/libvirtd.conf" as 4
2. set value of "log_outputs" in "/etc/libvirt/libvirtd.conf" as "1:stderr"
3. if libvirtd process is running, kill it
    # kill `pidof libvirtd`
4. start it in foreground:
   # libvirtd

   
A: with the old libvirt libvirt-0.8.7-1.el6.x86_64.rpm
   a. virsh destroy guest
   b. virsh start guest
20:31:16.079: 7838: warning : qemudDispatchSignalEvent:403 : Shutting down on signal 2
20:32:51.897: 8217: warning : qemudStartVMDaemon:3233 : Executing /usr/libexec/qemu-kvm
20:32:51.908: 8217: warning : qemudStartVMDaemon:3246 : Executing done /usr/libexec/qemu-kvm


B: with the new libvirt libvirt-0.8.7-3.el6
   a. virsh destroy guest
   b. virsh start guest
20:25:16.079: 7838: warning : qemudDispatchSignalEvent:403 : Shutting down on signal 2
20:25:16.403: 6453: warning : qemudStartVMDaemon:3239 : Executing /usr/libexec/qemu-kvm
20:25:16.413: 6453: warning : qemudStartVMDaemon:3249 : Executing done /usr/libexec/qemu-kvm


Seems there are no differences from two libvirtd.log . So would you please give me some suggestion on how to verify this bug ?

you should set log_level to "1", and check debug log.

tried the following things , but I'm not sure they are correct to get any
conclusion to verify this bug :

1. set value of "log_level" in "/etc/libvirt/libvirtd.conf" as 1
2. set value of "log_outputs" in "/etc/libvirt/libvirtd.conf" as "1:file:libvirtd.log"
3. if libvirtd process is running, kill it
    # kill `pidof libvirtd`
4. start it in foreground:
   # libvirtd


A: with the old libvirt libvirt-0.8.7-1.el6.x86_64.rpm
   a. virsh destroy guest
   b. virsh start guest
   c. grep domain -i libvirtd.log

06:02:20.040: 4930: debug : virDomainLookupByUUID:2103 : conn=0x7f2218000bd0, uuid=<removed>


B: with the new libvirt libvirt-0.8.7-3.el6
   a. virsh destroy guest
   b. virsh start guest
   c. grep domain -i libvirtd.log

05:59:37.044: 4500: debug : virDomainFree:2294 : dom=0x7f3e8c0008e0, (VM: name=foo, uuid=79ce5c1a-4f45-4531-99e3-fc8a3a479072), 
05:59:37.046: 4497: debug : virDomainLookupByUUID:2124 : conn=0x7f3ea0000bd0, uuid=79ce5c1a-4f45-4531-99e3-fc8a3a479072
05:59:37.046: 4497: debug : virDomainFree:2294 : dom=0x7f3e9c000920, (VM: name=foo, uuid=79ce5c1a-4f45-4531-99e3-fc8a3a479072), 

from the above we can see the new libvirt rpm includes the VM name/uuid/etc in domain messages and resolved the garbled words problem . 
So set the bug status to VERIFIED

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHBA-2011-0596.html

This patch introduced a regression, although it crashes the client and not libvirtd:
https://bugzilla.redhat.com/show_bug.cgi?id=711206