RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1121955 - virsh command takes long time to finish after set "log_level = 1" only
Summary: virsh command takes long time to finish after set "log_level = 1" only
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: libvirt
Version: 7.0
Hardware: x86_64
OS: Linux
high
high
Target Milestone: rc
: ---
Assignee: Peter Krempa
QA Contact: Virtualization Bugs
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-07-22 08:38 UTC by Wayne Sun
Modified: 2015-03-05 07:41 UTC (History)
8 users (show)

Fixed In Version: libvirt-1.2.8-1.el7
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-03-05 07:41:27 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
libvirtd log (3.86 MB, text/plain)
2014-07-22 09:13 UTC, Wayne Sun 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2015:0323 0 normal SHIPPED_LIVE Low: libvirt security, bug fix, and enhancement update 2015-03-05 12:10:54 UTC

Description Wayne Sun 2014-07-22 08:38:28 UTC 
Description of problem:
When set only "log_level = 1" in libvirtd.conf, restart libvirtd, then run virsh command will hang

Version-Release number of selected component (if applicable):
libvirt-1.1.1-29.el7.x86_64
systemd-208-2.el7.x86_64
kernel-3.10.0-123.el7.x86_64

How reproducible:
always

Steps to Reproduce:
1. edit libvirtd.conf
# vim /etc/libvirt/libvirtd.conf
...
log_level = 1
...

2. restart libvirtd
# systemctl restart libvirtd

# systemctl status libvirtd
libvirtd.service - Virtualization daemon
   Loaded: loaded (/usr/lib/systemd/system/libvirtd.service; enabled)
   Active: active (running) since Tue 2014-07-22 16:09:04 CST; 22min ago
 Main PID: 17530 (libvirtd)
   CGroup: /system.slice/libvirtd.service
           ├─ 3781 /sbin/dnsmasq --conf-file=/var/lib/libvirt/dnsmasq/default.conf
           └─17530 /usr/sbin/libvirtd

Jul 22 16:31:07 ibm-x3850x5-04.qe.lab.eng.nay.redhat.com libvirtd[17530]: Discarding device -1 0x7fd2400d86c0 /sys/devices/system/memory/memory90
Jul 22 16:31:07 ibm-x3850x5-04.qe.lab.eng.nay.redhat.com libvirtd[17530]: Failed to create node device for udev device '/sys/devices/system/memory/memory90'
Jul 22 16:31:07 ibm-x3850x5-04.qe.lab.eng.nay.redhat.com libvirtd[17530]: udev reports device 'memory900' does not have property 'DRIVER'
Jul 22 16:31:07 ibm-x3850x5-04.qe.lab.eng.nay.redhat.com libvirtd[17530]: Found property key 'SUBSYSTEM' value 'memory' for device with sysname 'memory900'
Jul 22 16:31:07 ibm-x3850x5-04.qe.lab.eng.nay.redhat.com libvirtd[17530]: Could not determine device type for device with sysfs name 'memory900'
Jul 22 16:31:07 ibm-x3850x5-04.qe.lab.eng.nay.redhat.com libvirtd[17530]: Discarding device -1 0x7fd2400ec3c0 /sys/devices/system/memory/memory900
Jul 22 16:31:07 ibm-x3850x5-04.qe.lab.eng.nay.redhat.com libvirtd[17530]: Failed to create node device for udev device '/sys/devices/system/memory/memory900'
Jul 22 16:31:08 ibm-x3850x5-04.qe.lab.eng.nay.redhat.com libvirtd[17530]: udev reports device 'memory901' does not have property 'DRIVER'
Jul 22 16:31:08 ibm-x3850x5-04.qe.lab.eng.nay.redhat.com libvirtd[17530]: Found property key 'SUBSYSTEM' value 'memory' for device with sysname 'memory901'
Jul 22 16:31:08 ibm-x3850x5-04.qe.lab.eng.nay.redhat.com libvirtd[17530]: Could not determine device type for device with sysfs name 'memory901'


3. run virsh list
# time virsh list

it will hang here

Actual results:
set log_level only will hang virsh command

Expected results:
virsh command could work with only set log_level as 1


Additional info:
if log_outputs set with file, it will not hang
Comment 1 Wayne Sun 2014-07-22 08:42:23 UTC 
This bug might be related:
https://bugzilla.redhat.com/show_bug.cgi?id=1105527
Comment 2 Wayne Sun 2014-07-22 09:05:38 UTC 
It's not totally hang, just take so long for it done.

# time virsh list
 Id    Name                           State
----------------------------------------------------


real	47m15.011s
user	0m0.021s
sys	0m0.016s
Comment 3 Wayne Sun 2014-07-22 09:13:08 UTC 
Created attachment 919849 [details]
libvirtd log

log collected with:
# journalctl -u libvirtd --since 16:00:00 >/tmp/libvirtd_log
Comment 4 Jiri Denemark 2014-07-22 09:31:07 UTC 
Looks like journald allows libvirtd to log only 9 messages per second and the next message is blocked until the next second. Is it a default installation of systemd or did you touch its configuration? What happens if you use older systemd?
Comment 5 Daniel Berrangé 2014-07-22 09:37:17 UTC 
Sigh, the log_level parameter really is such a worthless setting that just causes people pain. It is really only something you want to use when logging to stderr or a plain file

Currently libvirt.c uses this param to set the log level for the journal output

            if (virAsprintf(&tmp, "%d:journald", virLogGetDefaultPriority()) < 0)

I'd say we should probably restrict that so that the default journal output only at level INFO or higher. If someone really wants to log DEBUG to the journal  they can still set the log_outputs setting.
Comment 6 Wayne Sun 2014-07-22 11:09:48 UTC 
(In reply to Jiri Denemark from comment #4)
> Looks like journald allows libvirtd to log only 9 messages per second and
> the next message is blocked until the next second. Is it a default
> installation of systemd or did you touch its configuration? What happens if
> you use older systemd?


Yes, it's by default installation of systemd, without change configuration.

This also happen on:
systemd-207-8.el7.x86_64

I'll try to find older systemd later.
Comment 7 Wayne Sun 2014-07-23 09:41:11 UTC 
Did not find older systemd rhel7 host, tried this with fedora 19 on:

libvirt-1.0.5.1-1.fc19.x86_64
systemd-204-8.fc19.x86_64

and this problem did not happen.
Comment 8 Peter Krempa 2014-08-13 08:38:59 UTC 
Upstream now doesn't allow debug logging to journald if not specified explicitly via the log_outputs setting:

commit c018efa863a0be46628bc9437fc78dff6d8ee4a2
Author: Peter Krempa <pkrempa>
Date:   Tue Aug 12 16:10:39 2014 +0200

    daemon: Limit default log level to journald to VIR_LOG_INFO
    
    Libvirt is really chatty when the DEBUG log level is enabled. When a
    host uses journald we'd enable debug logging to journald when only
    specifying the debug log level. As journald may employ rate throttling
    this would lock up the daemon until it's able to flush all debug
    messages.
    
    This patch changes the default log level to VIR_LOG_INFO when using the
    default (unconfigured) log output to journald.
    
    To still allow debug logging to journald the user now has to explicitly
    specify journald as a log output with priority 1 in the "log_outputs"
    configuration option. This patch also changes the config file template
    to be explicit about this change and notify the user about the possible
    consequence of debug logging into journald.
    
    Resolves: https://bugzilla.redhat.com/show_bug.cgi?id=1121955

commit 7b6228d159578cddf0834336fab3d93b98bc0e96
Author: Peter Krempa <pkrempa>
Date:   Tue Aug 12 16:05:36 2014 +0200

    libvirtd: conf: Mention support for logging into journald
    
    Our docs didn't mention the explicit option to log into journald.

v1.2.7-54-gc018efa
Comment 10 zhengqin 2014-09-04 06:33:01 UTC 
Verify this issue with build libvirt-1.2.8-1.el7.x86_64:

Verify steps:
1. edit libvirtd.conf
# vim /etc/libvirt/libvirtd.conf
...
log_level = 1
...

2. restart libvirtd
# systemctl restart libvirtd

3. run virsh list
# time virsh list
 Id    Name                           State
----------------------------------------------------


real	0m0.013s
user	0m0.008s
sys	0m0.002s
# time virsh list
 Id    Name                           State
----------------------------------------------------


real	0m0.012s
user	0m0.007s
sys	0m0.002s


Virsh command does not take long time here.
Comment 11 Luyao Huang 2014-11-27 09:18:10 UTC 
Verify this bug with libvirt-1.2.8-9.el7.x86_64；

1.set /etc/libvirt/libvirtd.conf

log_level = 1

also test with set:

log_level = 1
log_outputs="1:journald"

2.restart libvirtd

# service libvirtd restart
Redirecting to /bin/systemctl restart  libvirtd.service

3.check log output in /var/log/message
Nov 27 17:13:52 dhcp-66-71-72 libvirtd: 2014-11-27 09:13:52.876+0000: 15606: info : libvirt version: 1.2.8, package: 9.el7 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2014-11-25-09:14:30, x86-025.build.eng.bos.redhat.com)
Nov 27 17:13:52 dhcp-66-71-72 libvirtd: 2014-11-27 09:13:52.876+0000: 15606: debug : virLogParseOutputs:1105 : outputs=1:journald
Nov 27 17:13:52 dhcp-66-71-72 journal: libvirt version: 1.2.8, package: 9.el7 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2014-11-25-09:14:30, x86-025.build.eng.bos.redhat.com)
Nov 27 17:13:52 dhcp-66-71-72 journal: starting netlink event service with protocol 0
Nov 27 17:13:52 dhcp-66-71-72 journal: starting netlink event service with protocol 15
Nov 27 17:13:52 dhcp-66-71-72 systemd: Started Virtualization daemon.
Nov 27 17:13:52 dhcp-66-71-72 journal: dnsmasq version is 2.66, --bind-dynamic is present, SO_BINDTODEVICE is in use
Nov 27 17:13:52 dhcp-66-71-72 journal: Reloading iptables rules

4.test virsh command
# time virsh list --all
 Id    Name                           State
----------------------------------------------------
 -     crashvm                        shut off
 -     crashvm1                       shut off
 -     iscsi-qcow2                    shut off
 -     qcow                           shut off
 -     qcow2manual                    shut off
 -     r6                             shut off
 -     r6-qcow2                       shut off
 -     r6.5                           shut off
 -     r6test                         shut off
 -     r7-gluster                     shut off
 -     raw                            shut off
 -     test1                          shut off
 -     test2                          shut off
 -     test3                          shut off
 -     test4                          shut off
 -     test5                          shut off


real	0m0.241s
user	0m0.060s
sys	0m0.008s

And check the /etc/libvirt/libvirtd.conf
there is a doc:

#    x:journald
#      output to journald logging system
Comment 13 errata-xmlrpc 2015-03-05 07:41:27 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.

https://rhn.redhat.com/errata/RHSA-2015-0323.html
Note You need to log in before you can comment on or make changes to this bug.