Bug 1860716 - VDSM Traceback failure at the journal log on DEBUG mode
Summary: VDSM Traceback failure at the journal log on DEBUG mode
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: vdsm
Version: 4.4.0
Hardware: x86_64
OS: Linux
high
medium
Target Milestone: ovirt-4.4.2
: 4.4.2
Assignee: Nir Soffer
QA Contact: Shir Fishbain
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-07-26 21:06 UTC by Roni
Modified: 2020-10-22 09:47 UTC (History)
7 users (show)

Fixed In Version: vdsm-4.40.24
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-09-23 16:16:06 UTC
oVirt Team: Storage
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2020:3822 0 None None None 2020-09-23 16:16:22 UTC
oVirt gerrit 110479 0 master MERGED multipath: Fix bad log format 2020-10-22 09:47:01 UTC

Description Roni 2020-07-26 21:06:27 UTC
Description of problem:
Traceback appears at the journal log when VDSM is in full DEBUG level

Version-Release number of selected component (if applicable):
4.4.1.12
vdsm-4.40.22-1.el8ev.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Enable DEBUG mode for all VDSM sections under /etc/vdsm/logger.conf
2. systemctl restart vdsmd
3. run journalctl

Actual results:
Multiple Traceback appears at the journalctl log, see example below

Expected results:
Traceback is not expected 

Additional info:
the error at the journalctl:

Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]: --- Logging error ---
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]: Traceback (most recent call last):
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:   File "/usr/lib64/python3.6/logging/__init__.py", line 994, in emit
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:     msg = self.format(record)
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:   File "/usr/lib64/python3.6/logging/__init__.py", line 840, in format
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:     return fmt.format(record)
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:   File "/usr/lib64/python3.6/logging/__init__.py", line 577, in format
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:     record.message = record.getMessage()
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:   File "/usr/lib64/python3.6/logging/__init__.py", line 338, in getMessage
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:     msg = msg % self.args
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]: TypeError: must be real number, not Error
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]: Call stack:
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:   File "/usr/lib64/python3.6/threading.py", line 884, in _bootstrap
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:     self._bootstrap_inner()
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:   File "/usr/lib64/python3.6/threading.py", line 916, in _bootstrap_inner
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:     self.run()
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:   File "/usr/lib64/python3.6/threading.py", line 864, in run
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:     self._target(*self._args, **self._kwargs)
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:   File "/usr/lib/python3.6/site-packages/vdsm/common/concurrent.py", line 260, in run
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:     ret = func(*args, **kwargs)
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:   File "/usr/lib/python3.6/site-packages/vdsm/common/logutils.py", line 373, in _run
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]:     self._target.handle(record)
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]: Message: 'Ignoring scsi_id failure for device %s: %e'
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]: Arguments: ('/dev/dm-14', Error(['/usr/lib/udev/scsi_id', '--page=0x80', '--whitelisted', '--export', '--replace-whitespace', '--device=/dev/dm-14'], 1, b'', b''))
Jul 26 23:03:35 lynx25.lab.eng.tlv2.redhat.com daemonAdapter[563280]: --- Logging error ---


Message: 'Ignoring scsi_id failure for device %s: %e'
should be:
Message: 'Ignoring scsi_id failure for device %s: %s'

Comment 1 Nir Soffer 2020-07-26 21:11:53 UTC
Trivial fix, and probably only log issue, but I'm not 100% sure.

Comment 5 Shir Fishbain 2020-08-20 07:45:10 UTC
Verified
Multiple Traceback don't appear anymore at the journalctl log

vdsm-4.40.25-1.el8ev.x86_64
ovirt-engine-4.4.2.2-0.3.el8ev.noarch

Comment 9 errata-xmlrpc 2020-09-23 16:16:06 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 (RHV RHEL Host (ovirt-host) 4.4.z [ovirt-4.4.2]), 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://access.redhat.com/errata/RHBA-2020:3822


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