Bug 970133

Summary: [TEXT] vdsm passes a bogus character to syslog - Unable to update the volume
Product: Red Hat Enterprise Virtualization Manager Reporter: Jiri Belka <jbelka>
Component: vdsmAssignee: Sergey Gotliv <sgotliv>
Status: CLOSED DUPLICATE QA Contact:
Severity: low Docs Contact:
Priority: unspecified    
Version: 3.3.0CC: abaron, amureini, bazulay, hateya, iheim, lpeer, ykaul
Target Milestone: ---   
Target Release: 3.3.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: storage
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-06-30 13:51:35 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Storage RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
vdsm.log none

Description Jiri Belka 2013-06-03 13:53:58 UTC 
Description of problem:
I got this on console

Message from syslogd@dell-r210ii-04 at Jun  3 15:44:14 ...
 �<11>vdsm vm.Vm ERROR vmId=`5e20c541-aaca-4627-bbc5-cd0d19d5e893`::Unable to update the volume 850c028e-af35-41b7-8bf9-87d6d70c4604 (domain: cc4d884d-15d9-4e35-b869-4330245c1b94 image: 8d92254e-c574-4919-8be1-7178bbce912e) for the drive vda

See part in the beginning of the line.

[root@dell-r210ii-04 ~]# grep vdsm /var/log/messages | grep '<[0-9][0-9]>'
Jun  3 15:39:02 dell-r210ii-04 �<11>vdsm vm.Vm ERROR vmId=`5e20c541-aaca-4627-bbc5-cd0d19d5e893`::Unable to update the volume 850c028e-af35-41b7-8bf9-87d6d70c4604 (domain: cc4d884d-15d9-4e35-b869-4330245c1b94 image: 8d92254e-c574-4919-8be1-7178bbce912e) for the drive vda
Jun  3 15:41:02 dell-r210ii-04 �<11>vdsm vm.Vm ERROR vmId=`5e20c541-aaca-4627-bbc5-cd0d19d5e893`::Unable to update the volume 850c028e-af35-41b7-8bf9-87d6d70c4604 (domain: cc4d884d-15d9-4e35-b869-4330245c1b94 image: 8d92254e-c574-4919-8be1-7178bbce912e) for the drive vda
Jun  3 15:44:14 dell-r210ii-04 �<11>vdsm vm.Vm ERROR vmId=`5e20c541-aaca-4627-bbc5-cd0d19d5e893`::Unable to update the volume 850c028e-af35-41b7-8bf9-87d6d70c4604 (domain: cc4d884d-15d9-4e35-b869-4330245c1b94 image: 8d92254e-c574-4919-8be1-7178bbce912e) for the drive vda

Comparison with other vdsm messages

[root@dell-r210ii-04 ~]# egrep 'vdsm.*ERROR' /var/log/messages | tail -n1
Jun  3 15:48:24 dell-r210ii-04 vdsm vm.Vm ERROR vmId=`5e20c541-aaca-4627-bbc5-cd0d19d5e893`::Stats function failed: <AdvancedStatsFunction _sampleDiskLatency at 0x14fc5f0>#012Traceback (most recent call last):#012  File "/usr/share/vdsm/sampling.py", line 351, in collect#012    statsFunction()#012  File "/usr/share/vdsm/sampling.py", line 226, in __call__#012    retValue = self._function(*args, **kwargs)#012  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleDiskLatency#012    vmDrive.name, flags=libvirt.VIR_TYPED_PARAM_STRING_OKAY)#012  File "/usr/share/vdsm/libvirtvm.py", line 554, in f#012    raise toe#012TimeoutError: Timed out during operation: cannot acquire state change lock

So seems related only to 'Unable to update the volume' messages.

Version-Release number of selected component (if applicable):
is1 / vdsm-4.10.3-0.416.git5358ed2.el6.x86_64

How reproducible:
100%

Steps to Reproduce:
1. have a running vm
2. block access to storage on vm's host
3.

Actual results:
bogus char in vdsm syslog message

Expected results:
clean message

Additional info:
I got this message after blocking access to storage on the host (iptables -I INPUT -s $storage_ip -j DROP).
Comment 1 Jiri Belka 2013-06-03 13:55:46 UTC 
Created attachment 756317 [details]
vdsm.log
Comment 3 Sergey Gotliv 2013-06-30 13:51:35 UTC 
The bug is in Python(2.6) implementation of SysLogHandler, which is used by us to handle sys log messages. The problem is already fixed in Python 2.7, but we unfortunately we are still using 2.6 in RHEL.

You can find original Python's bug here:
http://bugs.python.org/issue14452

The following link providing more details about the problem:
http://bugs.centos.org/view.php?id=6447

By the way, messages that don't need formatting are handled correctly, that's the reason why other examples provided in bug description looking just fine.

I backported solution from 2.7 to 2.6 on my machine and verified that it resolves the problem.

*** This bug has been marked as a duplicate of bug 845802 ***