Bug 1133955 - libvirtd doesn't log vdsm-related messages with vdsm-4.14.x
Summary: libvirtd doesn't log vdsm-related messages with vdsm-4.14.x
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: vdsm
Version: 3.4.0
Hardware: x86_64
OS: Linux
high
high
Target Milestone: ---
: 3.5.0
Assignee: Mooli Tayer
QA Contact: Pavel Stehlik
URL:
Whiteboard: infra
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-08-26 14:15 UTC by Gordon Watson
Modified: 2019-04-28 10:06 UTC (History)
14 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-09-09 12:43:42 UTC
oVirt Team: Infra
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 1173603 0 None None None Never

Description Gordon Watson 2014-08-26 14:15:42 UTC
Description of problem:

If VDSM has been upgraded on a RHEL 6.5 host from vdsm-4.13.0 to vdsm-4.14.x, then it is possible that libvirtd may no longer log any vdsm-related messages. 

The vdsm-4.14.x version of '/usr/libexec/vdsm/libvirt_configure.sh'
still contains;

BY_VDSM_VERS="4.13.0"


If an active "log_filters" line does not exist in '/etc/libvirt/libvirtd.conf', when VDSM is started and '/usr/libexec/vdsm/libvirt_configure.sh' is executed it will find entries in '/etc/libvirt/libvirtd.conf' containing "4.13.0" and not "configure libvirt", reporting "libvirt is already configured for vdsm". These entries would have been written previously by vdsm-4.13.0;

## beginning of configuration section by vdsm-4.13.0
## end of configuration section by vdsm-4.13.0


As a result no 'log_filters' entry will exist in '/etc/libvirt/libvirtd.conf' and libvirtd will not log any vdsm-related messages. When libvirtd starts it will log;

2014-08-10 16:32:18.781+0000: 9302: info : libvirt version: 0.10.2, package: 29.el6_5.9 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>;, 2014-05-29-05:18:21, x86-022.build.eng.bos.redhat.com)
2014-08-10 16:32:18.781+0000: 9302: error : virNWFilterSnoopLeaseFileRefresh:1903 : open("/var/run/libvirt/network/nwfilter.ltmp"): No such file or directory
2014-08-10 16:32:19.889+0000: 9302: error : virExecWithHook:426 : Cannot find 'pm-is-supported' in path: No such file or directory
2014-08-10 16:32:19.889+0000: 9302: warning : qemuCapsInit:863 : Failed to get host power management capabilities
2014-08-10 16:32:20.490+0000: 9302: error : virExecWithHook:426 : Cannot find 'pm-is-supported' in path: No such file or directory
2014-08-10 16:32:20.490+0000: 9302: warning : lxcCapsInit:77 : Failed to get host power management capabilities
2014-08-10 16:33:13.075+0000: 9184: error : virNetSocketReadWire:1194 : End of file while reading data: Input/output error
2014-08-10 16:33:18.574+0000: 9184: error : virNetSocketReadWire:1194 : End of file while reading data: Input/output error
2014-08-10 16:33:23.058+0000: 9212: error : virExecWithHook:426 : Cannot find 'pm-is-supported' in path: No such file or directory
2014-08-10 16:33:23.058+0000: 9212: warning : qemuCapsInit:863 : Failed to get host power management capabilities


Also, none of the other libvirt-specific entries for '/etc/libvirt/libvirtd.conf' will get written, e.g. the log file will not et updated to '/var/log/libvirt/libvirtd.log'.

Now, the chances of this happening on a RHEL host are not that high, I would say, as presumably an active 'log_filters' entry would have previously existed in '/etc/libvirt/libvirtd.conf'. However, there are two side effects here;

1) As I just mentioned the other 'libvirt' settings in '/usr/libexec/vdsm/libvirt_configure.sh' will not get set. 'libvirtd' will log vdsm-related messages as long as 'log_filters' exists, but whatever is trying to be set specifically by '/usr/libexec/vdsm/libvirt_configure.sh' won't be.

Obviously an easy work-around is to just manually add the 'log_filters' line to '/etc/libvirt/libvirtd.conf';

log_filters="3:virobject 3:virfile 2:virnetlink     3:cgroup 3:event 3:json 1:libvirt 1:util 1:qemu"


2) This is the BIG problem. On RHEV-H, there is an 'ovirt-node' script that explicitly removes the active 'log_filters' entry from '/etc/libvirt/libvirtd.conf' every time the system is booted. So, even 'log_filters' existed under vdsm-4.13.0 or even if you add the line manually to '/etc/libvirt/libvirtd.conf' it will get removed every time you boot.

This specific part of this problem is addressed in a separate RHEV-H bug that I haven't created yet. The intent of that bug however might be to suggest removing the line from the 'ovirt-node' script that removes the 'log_filters' entry, however even then as long as '/etc/libvirt/libvirtd.conf' contains "## beginning of configuration section by vdsm-4.13.0" and/or "## end of configuration section by vdsm-4.13.0" lines then both 'ovirt-early' and VDSM will execute '/usr/libexec/vdsm/libvirt_configure.sh' (via 'vdsm-tool') and neither will update '/etc/libvirt/libvirtd.conf'.

However, if such a change were made to 'ovirt-node' then a 'log_filters' line could be added manually to '/etc/libvirt/libvirtd.conf', which is already persisted, so this then would suffice. 

So, this bug is not as important as the RHEV-H that I will open shortly, but it will essentially still need the 'BY_VDSM_VERS' variable in '/usr/libexec/vdsm/libvirt_configure.sh' change to something like "4.14.x" in order for it work correctly. 

Also, the fact that the configuration of libvirt hinges on 'BY_VDSM_VERS' seems a bit fragile to me. However, if that is retained, then as we go forward with future releases then we should ensure that this gets updated accordingly.




Version-Release number of selected component (if applicable):

- RHEL 6.5 and RHEV-H 6.5 hosts with vdsm-4.14.x, upgraded from vdsm-4.13.0


How reproducible:


Steps to Reproduce:

1. Boot a RHEL 6.5 or RHEV-H 6.5 host with vdsm-4.14.x that has been upgraded from vdsm-4.13.0

2. VDSM will report "libvirt is already configured for vdsm"

3. If 'log_filters' exists in '/etc/libvirt/libvirtd.conf' then libvirtd logging will be ok, but if if doesn't exist, or if the host is RHEV-H then libvirtd will not log vdsm-related messages.


Actual results:


Expected results:


Additional info:

Comment 1 Gordon Watson 2014-08-26 14:49:03 UTC
The RHEV-H bug that I said that I would open is BZ 1133971.

Comment 3 Mooli Tayer 2014-09-09 10:48:28 UTC
FYI.
bug 1125237 - from version v4.17.X we will no longer 
use log_filters & log_outputs but instead use libvirt defaults.

Comment 4 Mooli Tayer 2014-09-09 12:43:42 UTC
(In reply to Gordon Watson from comment #0)
> Description of problem:
> 
> If VDSM has been upgraded on a RHEL 6.5 host from vdsm-4.13.0 to
> vdsm-4.14.x, then it is possible that libvirtd may no longer log any
> vdsm-related messages. 
> 
> The vdsm-4.14.x version of '/usr/libexec/vdsm/libvirt_configure.sh'
> still contains;

FYI, in newer versions this script has been removed  and replaced
with python code.

> 
> BY_VDSM_VERS="4.13.0"
> 
> 
> If an active "log_filters" line does not exist in
> '/etc/libvirt/libvirtd.conf', when VDSM is started and
> '/usr/libexec/vdsm/libvirt_configure.sh' is executed it will find entries in
> '/etc/libvirt/libvirtd.conf' containing "4.13.0" and not "configure
> libvirt", reporting "libvirt is already configured for vdsm". These entries
> would have been written previously by vdsm-4.13.0;
> 
> ## beginning of configuration section by vdsm-4.13.0
> ## end of configuration section by vdsm-4.13.0
> 
> 
> As a result no 'log_filters' entry will exist in
> '/etc/libvirt/libvirtd.conf' and libvirtd will not log any vdsm-related
> messages. When libvirtd starts it will log;
> 
> 2014-08-10 16:32:18.781+0000: 9302: info : libvirt version: 0.10.2, package:
> 29.el6_5.9 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>;,
> 2014-05-29-05:18:21, x86-022.build.eng.bos.redhat.com)
> 2014-08-10 16:32:18.781+0000: 9302: error :
> virNWFilterSnoopLeaseFileRefresh:1903 :
> open("/var/run/libvirt/network/nwfilter.ltmp"): No such file or directory
> 2014-08-10 16:32:19.889+0000: 9302: error : virExecWithHook:426 : Cannot
> find 'pm-is-supported' in path: No such file or directory
> 2014-08-10 16:32:19.889+0000: 9302: warning : qemuCapsInit:863 : Failed to
> get host power management capabilities
> 2014-08-10 16:32:20.490+0000: 9302: error : virExecWithHook:426 : Cannot
> find 'pm-is-supported' in path: No such file or directory
> 2014-08-10 16:32:20.490+0000: 9302: warning : lxcCapsInit:77 : Failed to get
> host power management capabilities
> 2014-08-10 16:33:13.075+0000: 9184: error : virNetSocketReadWire:1194 : End
> of file while reading data: Input/output error
> 2014-08-10 16:33:18.574+0000: 9184: error : virNetSocketReadWire:1194 : End
> of file while reading data: Input/output error
> 2014-08-10 16:33:23.058+0000: 9212: error : virExecWithHook:426 : Cannot
> find 'pm-is-supported' in path: No such file or directory
> 2014-08-10 16:33:23.058+0000: 9212: warning : qemuCapsInit:863 : Failed to
> get host power management capabilities
> 
> 
> Also, none of the other libvirt-specific entries for
> '/etc/libvirt/libvirtd.conf' will get written, e.g. the log file will not et
> updated to '/var/log/libvirt/libvirtd.log'.
> 
> Now, the chances of this happening on a RHEL host are not that high, I would
> say, as presumably an active 'log_filters' entry would have previously
> existed in '/etc/libvirt/libvirtd.conf'. However, there are two side effects
> here;

Everything up to here describes normal vdsm-tool behavior.

The tool adds a configuration section in each one of impacted
files between comments. We do not make any effort to test if 
this section was changed manually(user might want to make changes
look at this case for example, why not let the user change logging).

The BY_VDSM_VERS="4.13.0" is changed not when a new version 
is out but when the configuration actually changes, so we
intentionally don't want to upgrade it in that case.

It is a little confusing that the version number we use is
similar to a vdsm version but actually means something different.
Changing this should be considered well since it means changing 
how we used to do things.
You are welcome to open a bug if you want (assign to me if so).


> 
> 1) As I just mentioned the other 'libvirt' settings in
> '/usr/libexec/vdsm/libvirt_configure.sh' will not get set. 'libvirtd' will
> log vdsm-related messages as long as 'log_filters' exists, but whatever is
> trying to be set specifically by '/usr/libexec/vdsm/libvirt_configure.sh'
> won't be.
> 
> Obviously an easy work-around is to just manually add the 'log_filters' line
> to '/etc/libvirt/libvirtd.conf';
> 
> log_filters="3:virobject 3:virfile 2:virnetlink     3:cgroup 3:event 3:json
> 1:libvirt 1:util 1:qemu"
> 

FYI in newer vdsm versions (4.16.0?) we have exactly for this:
vdsm-tool configure --force

That will rewrite the section anyway.

> 
> 2) This is the BIG problem. On RHEV-H, there is an 'ovirt-node' script that
> explicitly removes the active 'log_filters' entry from
> '/etc/libvirt/libvirtd.conf' every time the system is booted. So, even
> 'log_filters' existed under vdsm-4.13.0 or even if you add the line manually
> to '/etc/libvirt/libvirtd.conf' it will get removed every time you boot.
> 
> This specific part of this problem is addressed in a separate RHEV-H bug
> that I haven't created yet. The intent of that bug however might be to
> suggest removing the line from the 'ovirt-node' script that removes the
> 'log_filters' entry, however even then as long as
> '/etc/libvirt/libvirtd.conf' contains "## beginning of configuration section
> by vdsm-4.13.0" and/or "## end of configuration section by vdsm-4.13.0"
> lines then both 'ovirt-early' and VDSM will execute
> '/usr/libexec/vdsm/libvirt_configure.sh' (via 'vdsm-tool') and neither will
> update '/etc/libvirt/libvirtd.conf'.
> 
> However, if such a change were made to 'ovirt-node' then a 'log_filters'
> line could be added manually to '/etc/libvirt/libvirtd.conf', which is
> already persisted, so this then would suffice. 
> 
> So, this bug is not as important as the RHEV-H that I will open shortly, but
> it will essentially still need the 'BY_VDSM_VERS' variable in
> '/usr/libexec/vdsm/libvirt_configure.sh' change to something like "4.14.x"
> in order for it work correctly. 
> 

If node previously removed a line from a config file, and you are suggesting
that that line should not be removed, than that bug/patch should include
handling rewriting it in a node specific flow as part of bug 1133971.

Also notice there might be a good reason for removing that line
(as we ended up doing in the general case, see comment 3).
Douglas will probably have an answer for that on bug 1133971.

> Also, the fact that the configuration of libvirt hinges on 'BY_VDSM_VERS'
> seems a bit fragile to me. However, if that is retained, then as we go
> forward with future releases then we should ensure that this gets updated
> accordingly.
> 

Indeed.

It is our responsibility to remember bumping the version when we make changes.

> 
> 
> 
> Version-Release number of selected component (if applicable):
> 
> - RHEL 6.5 and RHEV-H 6.5 hosts with vdsm-4.14.x, upgraded from vdsm-4.13.0
> 
> 
> How reproducible:
> 
> 
> Steps to Reproduce:
> 
> 1. Boot a RHEL 6.5 or RHEV-H 6.5 host with vdsm-4.14.x that has been
> upgraded from vdsm-4.13.0
> 
> 2. VDSM will report "libvirt is already configured for vdsm"
> 
> 3. If 'log_filters' exists in '/etc/libvirt/libvirtd.conf' then libvirtd
> logging will be ok, but if if doesn't exist, or if the host is RHEV-H then
> libvirtd will not log vdsm-related messages.
> 
> 
> Actual results:
> 
> 
> Expected results:
> 
> 
> Additional info:


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