Bug 694516

Summary:

[6.2 FEAT] Event logging framework for libvirt

Product:

Red Hat Enterprise Linux 6

Reporter:

IBM Bug Proxy <bugproxy>

Component:

libvirt

Assignee:

Jiri Denemark <jdenemar>

Status:

CLOSED ERRATA

QA Contact:

Virtualization Bugs <virt-bugs>

Severity:

medium

Docs Contact:

Priority:

medium

Version:

6.2

CC:

dallan, dyuan, eblake, jjarvis, mzhan, nobody+PNT0273897, rwu, sbest

Target Milestone:

beta

Keywords:

FutureFeature

Target Release:

6.2

Hardware:

x86_64

OS:

All

Whiteboard:

Fixed In Version:

libvirt-0.9.2-1.el6

Doc Type:

Enhancement

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2011-12-06 11:04:48 UTC

Type:

---

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

---

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Bug Depends On:

Bug Blocks:

638197, 659725, 693512

Attachments:

Description	Flags
Patch for enabling env variable support for virsh logging	none

Description IBM Bug Proxy 2011-04-07 14:32:42 UTC

1. Feature Overview:
Feature Id: [71085]
a. Name of Feature: [6.2 FEAT] Event logging framework for libvirt
b. Feature Description
Libvirt is an important component of the Linux virtualization stack. Its been found that for better
understanding and debugging of the virtualization infrastructure, a lightweight framework to track
libvirt event infrastructure state changes with an accurate timestamp is absolutely necessary. We
are working on an ancillary framework that would either be a daemon or integrated with libvirt,
through which we can track the state changes with accurate timestamping for a low overhead time
ordered event logging framework. This is under development and we intend to push this to the
upstream libvirt repository.

2. Feature Details:
Sponsor: LTC RAS
Architectures: x86, x86_64,
Arch Specificity: purely common code
Affects Kernel Modules: No
Delivery Mechanism: Direct from Community
Category: other
Request Type: Toolchain - Enhancement from Upstream
d. Upstream Acceptance: Not Started
Sponsor Priority P3
f. Severity: normal
IBM Confidential: No
Code Contribution: IBM code
g. Component Version Target: ---

3. Business Case
As virtualization becomes de-facto for cloud solutions and critical customer deployments, ability to
understand the transitions and workings of the full stack is imperative in order for service
personnel and sysamdin to understand the path and timeline of code execution and state transitions
for debugging, tuning and development of features in the virtualization stack. Currently libvirt is
an opaque layer in the virtualization infrastructure stack and this work will help mitigate the
situation to an extent.

4. Primary contact at Red Hat:
John Jarvis, jjarvis

5. Primary contacts at Partner:
Project Management Contact:
Michael W. Wortman, wortman.com

Technical contact(s):
Ananth Narayan M G, ananth.narayan.com

Comment 2 RHEL Program Management 2011-04-07 14:44:18 UTC

Since RHEL 6.1 External Beta has begun, and this bug remains
unresolved, it has been rejected as it is not proposed as
exception or blocker.

Red Hat invites you to ask your support representative to
propose this request, if appropriate and relevant, in the
next release of Red Hat Enterprise Linux.

Comment 3 IBM Bug Proxy 2011-05-20 11:40:20 UTC

------- Comment From skannery.com 2011-05-20 07:35 EDT-------
As part of making libvirt and virsh logging infrastruture better, added environment variable support for virsh logging.

Please find details of the patches sent upstream:
1. commit : 3c36f936b98e76cefbc088620d91b08dd3b81116
2. Discussion thread: http://www.mail-archive.com/libvir-list@redhat.com/msg37353.html

Currently a virsh process logs traces to the file specified in the command line (-l option). Multiple instances of virsh, thus requires same log file to be mentioned in command line of each of the instances. To avoid this,  two new environment variables are used to control virsh log level and log file - "VIRSH_DEBUG" and "VIRSH_LOG_FILE"

Will be attaching the ported patch soon. Please let me know if you need any more info related to this feature.

Comment 4 IBM Bug Proxy 2011-05-20 15:43:20 UTC

Created attachment 500083 [details]
Patch for enabling env variable support for virsh logging


------- Comment on attachment From skannery.com 2011-05-20 11:39 EDT-------


Attaching the patch for enabling environment variable support for virsh logging.

Two new  environment variables are defined:

a. VIRSH_DEBUG=<log_level>
   log_level can be a value between 0 - 4, where
   0 -> "DEBUG"
   1 -> "INFO"
   2 -> "NOTICE"
   3 -> "WARNING"
   4 -> "ERROR"

b. VIRSH_LOG_FILE=<logfile-path-and-name>
   logfile-path-and-name is the name and complete path for the log file.

Comment 6 Jiri Denemark 2011-06-07 20:24:47 UTC

This is now implemented upstream by v0.9.1-213-g3c36f93:

commit 3c36f936b98e76cefbc088620d91b08dd3b81116
Author: Supriya Kannery <supriyak.com>
Date:   Mon May 9 12:38:06 2011 +0530

    virsh: Use Env variables for debug level and logfile
    
    Use variables VIRSH_DEBUG and VIRSH_LOG_FILE for controlling virsh logging.
    
    Signed-off-by: Supriya Kannery <supriyak.com>

Comment 7 Jiri Denemark 2011-06-07 20:26:55 UTC

Actually, that patch seems to be just one small part of this feature. Resetting back to ASSIGNED.

Comment 8 Dave Allan 2011-06-14 18:27:55 UTC

Can someone from IBM comment on whether IBM will be submitting further work in this area?

Comment 10 IBM Bug Proxy 2011-06-16 15:06:08 UTC

------- Comment From skannery.com 2011-06-16 10:57 EDT-------
(In reply to comment #10)
> Can someone from IBM comment on whether IBM will be submitting further work in
> this area?

With the existing libvirt tracing infrastructure and virsh tracing patch we submitted, the event tracing infrastructure requirement for libvirt is already addressed.  Yet, we would like to get both virsh and libvirt log into a single file. So we have plans to submit patches for the same.

Comment 11 Dave Allan 2011-06-16 20:29:10 UTC

The upstream code acceptance deadline was actually today, although we can certainly make an exception for this code if you feel like you can get it submitted relatively quickly.  When do you think you might be able to submit it?

Comment 12 IBM Bug Proxy 2011-06-17 04:40:50 UTC

------- Comment From skannery.com 2011-06-17 00:35 EDT-------
(In reply to comment #12)
> The upstream code acceptance deadline was actually today, although we can
> certainly make an exception for this code if you feel like you can get it
> submitted relatively quickly.  When do you think you might be able to submit
> it?

Necessary patches for 6.2 are done. So the patches that I mentioned in my previous comment (combining virsh and libvirt logging), we can possibly get those done for 6.3 .

Comment 13 Dave Allan 2011-06-20 18:28:04 UTC

Ok, thanks; I'll put this BZ in POST to reflect that the VIRSH_DEBUG and VIRSH_LOG_FILE environment variable work is done.  Would you mind filing a separate bug for any further work you are planning?

Comment 14 Daniel Veillard 2011-06-23 03:07:08 UTC

This should be fixed by the libvirt-0.9.2-1.el6 rebase

Comment 17 Min Zhan 2011-06-24 06:37:01 UTC

According to Comment #13, I only check VIRSH_DEBUG and VIRSH_LOG_FILE environment variables in this bug. From the steps below I think the variables can work. But log in debug,info and error mode seems the same. I think log in debug mode should only display with *debug* info, log in error mode should display *debug/info/notice/warning/error* all info. Please confirm if it is right, thanks

Environment:
2.6.32-156.el6.x86_64
qemu-kvm-0.12.1.2-2.165.el6.x86_64
libvirt-0.9.2-1.el6.x86_64

Steps:
1.####Check debug level as Debug####
# export VIRSH_LOG_FILE=/tmp/debug.log

# export VIRSH_DEBUG=0 

# echo $VIRSH_DEBUG
0

# echo $VIRSH_LOG_FILE
/tmp/debug.log

# ll /tmp/debug.log
ls: cannot access /tmp/debug.log: No such file or directory

# virsh list --all
 Id Name                 State
----------------------------------
  - rhel61               shut off

# virsh start rhel61
Domain rhel61 started

# cat /tmp/debug.log
[2011.06.23 13:49:28 virsh 25068] DEBUG start: found option <domain>: rhel61
[2011.06.23 13:49:28 virsh 25068] DEBUG start: <domain> trying as domain NAME

# virsh start rhel61
error: Domain is already active

# cat /tmp/debug.log
[2011.06.23 13:49:28 virsh 25068] DEBUG start: found option <domain>: rhel61
[2011.06.23 13:49:28 virsh 25068] DEBUG start: <domain> trying as domain NAME
[2011.06.23 13:49:44 virsh 25124] DEBUG start: found option <domain>: rhel61
[2011.06.23 13:49:44 virsh 25124] DEBUG start: <domain> trying as domain NAME
[2011.06.23 13:49:44 virsh 25124] ERROR Domain is already active

# ll /tmp/debug.log 
-rw-r--r--. 1 root root 375 Jun 23 13:49 /tmp/debug.log

2. #####Check debug level as error####
# export VIRTSH_DEBUG=4

# echo $VIRSH_DEBUG
4

# export VIRSH_LOG_FILE=/tmp/error.log

# echo $VIRSH_LOG_FILE
/tmp/error.log
# ll /tmp/error.log
ls: cannot access /tmp/error.log: No such file or directory
# virsh list --all
 Id Name                 State
----------------------------------
  2 rhel61               running

# virsh destroy rhel61
Domain rhel61 destroyed
# cat /tmp/error.log
[2011.06.23 14:12:52 virsh 25452] DEBUG destroy: found option <domain>: rhel61
[2011.06.23 14:12:52 virsh 25452] DEBUG destroy: <domain> trying as domain NAME

# virsh destroy rhel61
libvir: QEMU error : Requested operation is not valid: domain is not running
error: Failed to destroy domain rhel61
error: Requested operation is not valid: domain is not running

# cat /tmp/error.log
[2011.06.23 14:12:52 virsh 25452] DEBUG destroy: found option <domain>: rhel61
[2011.06.23 14:12:52 virsh 25452] DEBUG destroy: <domain> trying as domain NAME
[2011.06.23 14:17:34 virsh 25548] DEBUG destroy: found option <domain>: rhel61
[2011.06.23 14:17:34 virsh 25548] DEBUG destroy: <domain> trying as domain NAME
[2011.06.23 14:17:34 virsh 25548] ERROR Failed to destroy domain rhel61
[2011.06.23 14:17:34 virsh 25548] ERROR Requested operation is not valid: domain is not running

3. ####Set debug level as Info#####
# export VIRSH_DEBUG=1

# echo $VIRSH_DEBUG
1
# export VIRSH_LOG_FILE=/tmp/info.log

# echo $VIRSH_LOG_FILE
/tmp/info.log

# ll /tmp/info.log
ls: cannot access /tmp/info.log: No such file or directory

# virsh destroy rhel61
libvir: QEMU error : Requested operation is not valid: domain is not running
error: Failed to destroy domain rhel61
error: Requested operation is not valid: domain is not running

# virsh start rhel61
Domain rhel61 started

# ll /tmp/info.log
-rw-r--r--. 1 root root 482 Jun 23 14:29 /tmp/info.log

# cat /tmp/info.log
[2011.06.23 14:29:30 virsh 25651] DEBUG destroy: found option <domain>: rhel61
[2011.06.23 14:29:30 virsh 25651] DEBUG destroy: <domain> trying as domain NAME
[2011.06.23 14:29:30 virsh 25651] ERROR Failed to destroy domain rhel61
[2011.06.23 14:29:30 virsh 25651] ERROR Requested operation is not valid: domain is not running
[2011.06.23 14:29:35 virsh 25659] DEBUG start: found option <domain>: rhel61
[2011.06.23 14:29:35 virsh 25659] DEBUG start: <domain> trying as domain NAME


-------
I can reproduce with Old pkg:libvirt-0.9.1-1.el6.x86_64, nothing will take effect for these 2 environment variable.

Steps:
# echo $VIRSH_LOG_FILE
/tmp/virsh.log

# echo $VIRSH_DEBUG
0

# ll /tmp/virsh.log
ls: cannot access /tmp/virsh.log: No such file or directory

# virsh start rhel61
Domain rhel61 started

# virsh destroy rhel61
Domain rhel61 destroyed

# ll /tmp/virsh.log
ls: cannot access /tmp/virsh.log: No such file or directory

Comment 18 Min Zhan 2011-06-24 06:50:59 UTC

Also I find another issue about virsh help/man page about debug level. Pls keep the consistence about debug level (0-4 or 0-5?) in help page and man page. Would these will be fixed in this bug? Or should we file a new bug to track? Please help to confirm, thanks

New pkg:libvirt-0.9.2-1.el6.x86_64

# virsh --help |grep debug
    -d | --debug <num>      debug level [0-4]

# man virsh
...

       -d, --debug LEVEL
           Enable debug messages at integer LEVEL and above.  LEVEL can range from
           0 (default) to 5.

 LIBVIRT_DEBUG=LEVEL
           Turn on verbose debugging of all libvirt API calls. Valid levels are

           ·   LIBVIRT_DEBUG=1

               Messages at level DEBUG or above

           ·   LIBVIRT_DEBUG=2

               Messages at level INFO or above

           ·   LIBVIRT_DEBUG=3

               Messages at level WARNING or above

           ·   LIBVIRT_DEBUG=4

               Messages at level ERROR or above


Old pkg:libvirt-0.9.1-1.el6.x86_64

1. # virsh -h |grep debug
    -d | --debug <num>      debug level [0-5]

2. # man virsh
...
       -d, --debug LEVEL
           Enable debug messages at integer LEVEL and above.  LEVEL can range from
           0 (default) to 5.

...
       LIBVIRT_DEBUG=LEVEL
           Turn on verbose debugging of all libvirt API calls. Valid levels are

           ·   LIBVIRT_DEBUG=1

               Messages at level DEBUG or above

           ·   LIBVIRT_DEBUG=2

               Messages at level INFO or above

           ·   LIBVIRT_DEBUG=3

               Messages at level WARNING or above

           ·   LIBVIRT_DEBUG=4

               Messages at level ERROR or above

Comment 19 IBM Bug Proxy 2011-06-24 11:30:30 UTC

------- Comment From skannery.com 2011-06-24 07:21 EDT-------
(In reply to comment #14)
For any further work, we will file new bug.

Comment 20 Jiri Denemark 2011-06-24 11:37:35 UTC

Heh, I should have looked at this series closer. The patch, the rest of the series was actually never finished by its author and thus not applied. Logging in virsh is currently just a big mess and setting VIRSH_DEBUG=N (or virsh -d N) has basically no effect for any N.

Comment 21 IBM Bug Proxy 2011-06-24 11:40:33 UTC

------- Comment From skannery.com 2011-06-24 07:30 EDT-------
(In reply to comment #16)
> According to Comment #13, I only check VIRSH_DEBUG and VIRSH_LOG_FILE
> environment variables in this bug. From the steps below I think the variables
> can work. But log in debug,info and error mode seems the same. I think log in
> debug mode should only display with *debug* info, log in error mode should
> display *debug/info/notice/warning/error* all info. Please confirm if it is
> right, thanks
>

Previous to this patch, virsh logging had the order that you specified, where for "DEBUG" only the debug messages logged and for "ERROR" messages at all the levels get logged.

But libvirt logging is done the other way, where "DEBUG" level displays messages from "ALL" other levels and "ERROR" displays 'ONLY' error messages. And that is the right usage of DEBUG and ERROR levels. So in this feature, I changed virsh logging to align to libvirt logging as specified under the section "Configuring logging in the library" at http://libvirt.org/logging.html.

Thanks,
Supriya

Comment 22 IBM Bug Proxy 2011-06-24 11:50:21 UTC

------- Comment From skannery.com 2011-06-24 07:44 EDT-------
(In reply to comment #17)
> Also I find another issue about virsh help/man page about debug level. Pls keep
> the consistence about debug level (0-4 or 0-5?) in help page and man page.
> Would these will be fixed in this bug? Or should we file a new bug to track?
> Please help to confirm, thanks
>

virsh can take log levels from 0 - 4 only as per how its coded. Debug level '5' mentioned in man page is a defect. There are few more existing defects with virsh tracing and logging that we need to resolve
like
a. Usage of magic numbers for logging instead of using log level variables in the code.
b. Uses log level '5' for logging message whereas '5' is not a valid log level.
c. discrepencies between the code and  documentation on log levels

These defects can be tracked through a new bug report. Can you please raise one?

Comment 23 IBM Bug Proxy 2011-06-24 12:10:22 UTC

------- Comment From skannery.com 2011-06-24 08:02 EDT-------
(In reply to comment #20)
> Heh, I should have looked at this series closer. The patch, the rest of the
> series was actually never finished by its author and thus not applied. Logging
> in virsh is currently just a big mess and setting VIRSH_DEBUG=N (or virsh -d N)
> has basically no effect for any N.

The core patch that contained the changes for applying environment variables has been accepted upstream and I have backported only that patch for inclusion into RHEL. Rest of the patches in the patchset were actually for resolving issues like magic number usage, incorrect log level order etc..(those I listed in comment #21) which are existing issues with virsh logging.

I will be resending those patches for fixing these defects  upstream. Please open a bug report for the same.
Thanks, Supriya

Comment 24 Min Zhan 2011-06-27 11:12:15 UTC

According to comment #22, I have filed a new Bug 716888 to track log level and
usage issue.

Comment 25 Jiri Denemark 2011-07-14 15:34:02 UTC

OK, since this BZ is only tracking the env. variable addition, which was already done (see comment #6), I'm moving this back to MODIFIED.

Comment 26 John Jarvis 2011-07-14 15:39:41 UTC

This enhancement request was evaluated by the full Red Hat Enterprise Linux
team for inclusion in a Red Hat Enterprise Linux minor release.   As a result
of this evaluation, Red Hat has tentatively approved inclusion of this feature
in the next Red Hat Enterprise Linux Update minor release.   While it is a goal
to include this enhancement in the next minor release of Red Hat Enterprise
Linux, the enhancement is not yet committed for inclusion in the next minor
release pending the next phase of actual code integration and successful Red
Hat and partner testing.

Comment 28 Min Zhan 2011-07-18 07:29:41 UTC

According to Comment #6 and Comment #25, Move to VERIFIED

Comment 29 IBM Bug Proxy 2011-10-25 11:40:31 UTC

------- Comment From skannery.com 2011-10-25 07:33 EDT-------
Verified in RHEL6.2 Snapshot2. Env variables for virsh for  debug level and log file are working fine.

Only part missing is the updation of these variables and their usage in virsh.pod file. Patches posted and accepted upstream, related to this,  are discussed in bug #72823 (Redhat bug #716888) .

Upstream discussion link : https://www.redhat.com/archives/libvir-list/2011-June/msg01574.html

- thanks, Supriya

Comment 30 Eric Blake 2011-10-25 15:07:06 UTC

(In reply to comment #29)
> Only part missing is the updation of these variables and their usage in
> virsh.pod file. Patches posted and accepted upstream, related to this,  are
> discussed in bug #72823 (Redhat bug #716888) .

bug 716888 is marked as fixed in libvirt-0.9.3-4.el6.

> 
> Upstream discussion link :
> https://www.redhat.com/archives/libvir-list/2011-June/msg01574.html

The patches in that email series were already included in upstream 0.9.4.  I don't see anything that you mentioned that should not already be present in RHEL6.2 Snapshot2.

Comment 31 errata-xmlrpc 2011-12-06 11:04:48 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

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