Bug 1416278 - schema inconsistencies flooding logs [NEEDINFO]
Summary: schema inconsistencies flooding logs
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: vdsm
Version: 4.0.6
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: ovirt-4.1.0-rc
: ---
Assignee: Irit Goihman
QA Contact: Jiri Belka
URL:
Whiteboard:
Depends On:
Blocks: 1416315
TreeView+ depends on / blocked
 
Reported: 2017-01-25 06:36 UTC by Germano Veit Michel
Modified: 2020-03-11 15:39 UTC (History)
14 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1416315 (view as bug list)
Environment:
Last Closed: 2017-04-25 00:55:53 UTC
oVirt Team: Infra
Target Upstream Version:
bmcclain: needinfo? (spower)


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 2888351 0 None None None 2017-01-25 06:59:34 UTC
Red Hat Product Errata RHEA-2017:0998 0 normal SHIPPED_LIVE VDSM bug fix and enhancement update 4.1 GA 2017-04-18 20:11:39 UTC
oVirt gerrit 71141 0 None None None 2017-01-25 08:30:59 UTC

Description Germano Veit Michel 2017-01-25 06:36:18 UTC
Description of problem:

vdsm flooding logs. Apparently this started after 4.0.6 upgrade.

On getAllVmStats, each VM generates a _report_inconsistency.

It goes like in the format below:

jsonrpc.Executor/0::DEBUG::2017-01-23 09:01:05,876::__init__::530::jsonrpc.JsonRpcServer::(_handle_request) Calling 'Host.getAllVmStats' in bridge with {}
jsonrpc.Executor/0::WARNING::2017-01-23 09:01:05,902::vdsmapi::147::devel::(_report_inconsistency) Provided parameters {...} do not match any of union VmStats values 
jsonrpc.Executor/0::WARNING::2017-01-23 09:01:05,904::vdsmapi::147::devel::(_report_inconsistency) Provided parameters {...} do not match any of union VmStats values 
jsonrpc.Executor/0::WARNING::2017-01-23 09:01:05,905::vdsmapi::147::devel::(_report_inconsistency) Provided parameters {...} do not match any of union VmStats values 
jsonrpc.Executor/0::WARNING::2017-01-23 09:01:05,908::vdsmapi::147::devel::(_report_inconsistency) Provided parameters {...} do not match any of union VmStats values 
[....]

Each {...} above is for each VM (see attached log file for more details).

How reproducible:
100%

In our labs, everything seems to fail schema check, not just getAllVmStats (our vdsm is slightly newer 4.0.6). Host devices, storage...

jsonrpc.Executor/2::WARNING::2017-01-25 01:26:59,383::vdsmapi::147::devel::(_report_inconsistency) Parameter spmLver is not int type
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,422::vdsmapi::147::devel::(_report_inconsistency) Following parameters ['type'] were not recognized
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,422::vdsmapi::147::devel::(_report_inconsistency) Parameter lver is not int type
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,422::vdsmapi::147::devel::(_report_inconsistency) Parameter version is not int type
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,422::vdsmapi::147::devel::(_report_inconsistency) Required property domainType is not provided when calling StoragePool.getInfo
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,423::vdsmapi::147::devel::(_report_inconsistency) Following parameters ['isoprefix'] were not recognized
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,423::vdsmapi::147::devel::(_report_inconsistency) Parameter diskfree is not int type
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,423::vdsmapi::147::devel::(_report_inconsistency) Parameter disktotal is not int type
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,423::vdsmapi::147::devel::(_report_inconsistency) Following parameters ['isoprefix'] were not recognized
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,423::vdsmapi::147::devel::(_report_inconsistency) Required property diskfree is not provided when calling StoragePool.getInfo
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,423::vdsmapi::147::devel::(_report_inconsistency) Required property disktotal is not provided when calling StoragePool.getInfo
jsonrpc.Executor/5::WARNING::2017-01-25 01:27:00,423::vdsmapi::147::devel::(_report_inconsistency) Required property version is not provided when calling StoragePool.getInfo


jsonrpc.Executor/2::WARNING::2017-01-25 01:25:54,719::vdsmapi::147::devel::(_report_inconsistency) Parameter {'pci_0000_ff_17_0': {'params': {'product': 'Xeon E7 v3/Xeon E5 v3/Core i7 Integra
ted Memory Controller 1 Channel 0 Thermal Control', 'vendor': 'Intel Corporation', 'product_id': '0x2fd0', 'parent': 'computer', 'vendor_id': '0x8086', 'driver': 'hswep_uncore', 'capability':
 'pci', 'is_assignable': 'true', 'address': {'slot': '23', 'bus': '255', 'domain': '0', 'function': '0'}}}, 'pci_0000_ff_17_4': {'params': {'product': 'Xeon E7 v3/Xeon E5 v3/Core i7 DDRIO (VM
SE) 2 & 3', 'vendor': 'Intel Corporation', 'product_id': '0x2fb8', 'parent': 'computer', 'vendor_id': '0x8086', 'capability': 'pci', 'is_assignable': 'true', 'address': {'slot': '23', 'bus': 
'255', 'domain': '0', 'function': '4'}}}, 'pci_0000_ff_17_5': {'params': {'product': 'Xeon E7 v3/Xeon E5 v3/Core i7 DDRIO (VMSE) 2 [...]

Version-Release number of selected component (if applicable):
ovirt-engine-4.0.6.3-0.1.el7ev.noarch
vdsm-4.18.15.3-1.el7ev (4.0.5)

We have internally a similar issue on (our labs)
ovirt-engine-4.0.6.3-0.1.el7ev.noarch
vdsm-4.18.21-1.el7ev.x86_64

This doesn't seem to make much difference on our labs, it's still flooding the same way.
https://gerrit.ovirt.org/#/c/59512/
https://bugzilla.redhat.com/show_bug.cgi?id=1348256
[devel]
python_warnings_enable = false

Actual results:
vdsm.log and /var/log/messages flooded, hosts running low on space.

Expected results:
No flooding of logs due to schema inconsistencies.

Comment 12 Sandro Bonazzola 2017-01-26 16:50:30 UTC
The fix for this seems to be included in v4.19.3 which is going to be released within oVirt 4.1.0 RC2. I would suggest to update target milestone accordingly.

Comment 13 Dan Kenigsberg 2017-01-29 12:23:02 UTC
Germano, do you know if anybody has ever edited /etc/vdsm/logger.conf manually? A pristine file should have been updated by rpm upgrade, and the [deve] section introduced to it.

Comment 14 Germano Veit Michel 2017-01-30 01:22:20 UTC
Dan, it doesn't need to be manually edited. And after reproducing it manually I am now more worried about it.

First of all. Adding this to the BZ.

How reproducible:
100%

Steps to Reproduce:
1. Install RHVH 4.0.4 and check logger.conf
# cat /etc/vdsm/logger.conf | grep devel | wc -l
0
2. Attach entitlements, update and reboot
---> Package redhat-virtualization-host-image-update.noarch 0:4.0-20170104.1.el7_3 will be obsoleting
---> Package redhat-virtualization-host-image-update-placeholder.noarch 0:4.0-4.2.el7 will be obsoleted

3. Check logger.conf
# cat /etc/vdsm/logger.conf | grep devel | wc -l
0

Versions:
Initial install: 4.0-20161018.0
Upgrade:         4.0-20170104.1

Interestingly, it's not only the logger.conf file. Pretty much every config file is with the older image timestamp after upgrade.

# ll /etc/vdsm/
total 32
-rw-r--r--. 1 root root  1747 Sep  7 21:14 logger.conf
drwxr-xr-x. 2 root root    17 Oct 13 00:02 logrotate
-rw-r--r--. 1 root root  3161 Sep  7 21:14 mom.conf
drwxr-xr-x. 2 root root  4096 Oct 13 00:02 mom.d
-rw-r--r--. 1 root root   619 Sep  7 21:14 svdsm.logger.conf
-rw-r--r--. 1 root root 12725 Sep  7 21:14 vdsm.conf
drwxr-xr-x. 2 root root     6 Sep  7 21:14 vdsm.conf.d

Whereas in a fresh 4.0-20170104.1 install:

# ll /etc/vdsm/
total 40
-rw-r--r--. 1 root root  1825 Dec 14 20:52 logger.conf
drwxr-xr-x. 2 root root  4096 Jan  5 01:33 logrotate
-rw-r--r--. 1 root root  3166 Dec 14 20:52 mom.conf
drwxr-xr-x. 2 root root  4096 Jan  5 01:33 mom.d
-rw-r--r--. 1 root root   619 Dec 14 20:52 svdsm.logger.conf
-rw-r--r--. 1 root root 12655 Dec 14 20:52 vdsm.conf
drwxr-xr-x. 2 root root  4096 Dec 14 20:52 vdsm.conf.d

Maybe this is actually something bigger that needs to be evaluated? logger.conf seems to be just one of many.

Comment 15 Dan Kenigsberg 2017-01-30 06:48:42 UTC
(In reply to Germano Veit Michel from comment #14)

> Interestingly, it's not only the logger.conf file. Pretty much every config
> file is with the older image timestamp after upgrade.
> 
> 
> Maybe this is actually something bigger that needs to be evaluated?
> logger.conf seems to be just one of many.


yes, please open another bug about rhvh-ng: unmodified configuration files are not updated during update.

Comment 16 Germano Veit Michel 2017-01-30 06:57:59 UTC
(In reply to Dan Kenigsberg from comment #15)
> yes, please open another bug about rhvh-ng: unmodified configuration files
> are not updated during update.

Done. https://bugzilla.redhat.com/show_bug.cgi?id=1417534

Comment 18 Jiri Belka 2017-01-31 09:55:24 UTC
Some 4.0.5 hypervisor:

[root@dell-r210ii-03 ~]# rpm -qf /etc/redhat-release 
redhat-release-virtualization-host-4.0-5.2.el7.x86_64

[root@dell-r210ii-03 ~]# sed -n '/^\[logger_.\+/,+2p' /etc/vdsm/logger.conf 
[logger_root]
level=DEBUG
handlers=syslog,logfile
[logger_vds]
level=DEBUG
handlers=syslog,logfile
[logger_Storage]
level=DEBUG
handlers=logfile
[logger_ovirt_hosted_engine_ha]
level=ERROR
handlers=
[logger_ovirt_hosted_engine_ha_config]
level=ERROR
handlers=
[logger_IOProcess]
level=INFO
handlers=logfile
[logger_connectivity]
level=DEBUG
handlers=connlogfile
[logger_virt]
level=DEBUG
handlers=logfile
[logger_devel]
level=ERROR
handlers=logfile

[root@dell-r210ii-03 ~]# find /etc/vdsm/ -type f -ls
738198194    4 -rw-r--r--   1 root     root          332 Nov 11 12:25 /etc/vdsm/logrotate/vdsm
805307017    4 -rw-r--r--   1 root     root          323 Nov 11 12:25 /etc/vdsm/mom.d/00-defines.policy
805307018    0 -rw-r--r--   1 root     root            0 Nov 11 12:25 /etc/vdsm/mom.d/01-parameters.policy
805307019    8 -rw-r--r--   1 root     root         5369 Nov 11 12:25 /etc/vdsm/mom.d/02-balloon.policy
805307020    8 -rw-r--r--   1 root     root         4651 Nov 11 12:25 /etc/vdsm/mom.d/03-ksm.policy
805307021    4 -rw-r--r--   1 root     root         2276 Nov 11 12:25 /etc/vdsm/mom.d/04-cputune.policy
805307022    4 -rw-r--r--   1 root     root         1105 Nov 11 12:25 /etc/vdsm/mom.d/05-iotune.policy
201327265    4 -rw-r--r--   1 root     root         1825 Nov 11 12:25 /etc/vdsm/logger.conf
201327266    4 -rw-r--r--   1 root     root         3161 Nov 11 12:25 /etc/vdsm/mom.conf
201327267    4 -rw-r--r--   1 root     root          619 Nov 11 12:25 /etc/vdsm/svdsm.logger.conf
201548801    4 -rw-r--r--   1 root     root           56 Jan 31 09:54 /etc/vdsm/vdsm.conf
201548800   16 -rw-r--r--   1 root     root        12654 Nov 11 12:25 /etc/vdsm/vdsm.conf.20170131095425
201548802    4 -rw-r--r--   1 root     root           37 Jan 31 09:54 /etc/vdsm/vdsm.id
[root@dell-r210ii-03 ~]# find /etc/vdsm/ -type f | xargs md5sum
9224553c367d8008d063a0b5d507f741  /etc/vdsm/logrotate/vdsm
961392dfcc365f0b338ccb5ff5467306  /etc/vdsm/mom.d/00-defines.policy
d41d8cd98f00b204e9800998ecf8427e  /etc/vdsm/mom.d/01-parameters.policy
50bbbea8a43d8c625ab0ecbfbfaf4f5b  /etc/vdsm/mom.d/02-balloon.policy
d662ff47e0c04390b065e09773538ebd  /etc/vdsm/mom.d/03-ksm.policy
6d0d82e69d6c6799cbe2cc69aadb2a2d  /etc/vdsm/mom.d/04-cputune.policy
bd9741692fa7a9d5d8a08e00b2f82f23  /etc/vdsm/mom.d/05-iotune.policy
63a31eaf8583903be947709caca3b98a  /etc/vdsm/logger.conf
f38473ccb4620c2a0c9d337fcf54d264  /etc/vdsm/mom.conf
84abb6997eaf8e3f732b848539da5165  /etc/vdsm/svdsm.logger.conf
97aac3bd146f2d2b32dfa5af2c184ab8  /etc/vdsm/vdsm.conf
9cd63a7a05a7e45271adf75c82d032bb  /etc/vdsm/vdsm.conf.20170131095425
a8175933284d9d84ca32a77bd6d389ed  /etc/vdsm/vdsm.id

Upgrading to latest 4.0.6 from CDN/Pulp:

[root@dell-r210ii-03 ~]# rpm -qf /etc/redhat-release 
redhat-release-virtualization-host-4.0-6.1.el7.x86_64

[root@dell-r210ii-03 ~]# sed -n '/^\[logger_.\+/,+2p' /etc/vdsm/logger.conf
[logger_root]
level=DEBUG
handlers=syslog,logfile
[logger_vds]
level=DEBUG
handlers=syslog,logfile
[logger_Storage]
level=DEBUG
handlers=logfile
[logger_ovirt_hosted_engine_ha]
level=ERROR
handlers=
[logger_ovirt_hosted_engine_ha_config]
level=ERROR
handlers=
[logger_IOProcess]
level=INFO
handlers=logfile
[logger_connectivity]
level=DEBUG
handlers=connlogfile
[logger_virt]
level=DEBUG
handlers=logfile
[logger_devel]
level=ERROR
handlers=logfile

[root@dell-r210ii-03 ~]# find /etc/vdsm/ -type f | xargs md5sum
9224553c367d8008d063a0b5d507f741  /etc/vdsm/logrotate/vdsm
961392dfcc365f0b338ccb5ff5467306  /etc/vdsm/mom.d/00-defines.policy
d41d8cd98f00b204e9800998ecf8427e  /etc/vdsm/mom.d/01-parameters.policy
50bbbea8a43d8c625ab0ecbfbfaf4f5b  /etc/vdsm/mom.d/02-balloon.policy
d662ff47e0c04390b065e09773538ebd  /etc/vdsm/mom.d/03-ksm.policy
6d0d82e69d6c6799cbe2cc69aadb2a2d  /etc/vdsm/mom.d/04-cputune.policy
bd9741692fa7a9d5d8a08e00b2f82f23  /etc/vdsm/mom.d/05-iotune.policy
63a31eaf8583903be947709caca3b98a  /etc/vdsm/logger.conf
f38473ccb4620c2a0c9d337fcf54d264  /etc/vdsm/mom.conf
84abb6997eaf8e3f732b848539da5165  /etc/vdsm/svdsm.logger.conf
97aac3bd146f2d2b32dfa5af2c184ab8  /etc/vdsm/vdsm.conf
9cd63a7a05a7e45271adf75c82d032bb  /etc/vdsm/vdsm.conf.20170131095425
a8175933284d9d84ca32a77bd6d389ed  /etc/vdsm/vdsm.id

# grep -c 'jsonrpc\.Executor.*vdsmapi' /var/log/vdsm/vdsm.log
0

Thus no DEBUG for logger_devel (see config files were not updated, see md5 checksums).

Comment 20 Jiri Belka 2017-02-02 12:57:55 UTC
ok

[root@dell-r210ii-13 ~]# sed -n '/def _report_inconsistency/,+5p' /usr/lib/python2.7/site-packages/api/vdsmapi.py
    def _report_inconsistency(self, message):
        if self._strict_mode:
            raise JsonRpcInvalidParamsError(message)

    def verify_args(self, rep, args):
        try:
[root@dell-r210ii-13 ~]# rpm -q vdsm-api
vdsm-api-4.19.4-1.el7ev.noarch
[root@dell-r210ii-13 ~]# grep -ic vdsmapi /var/log/vdsm/vdsm.log
0


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