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.
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.
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.
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.
(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.
(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
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).
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
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 1000 days