Bug 730062

Summary: Invalid string in json text passed to libvirt on SPICE_DISCONNECTED event.
Product: Red Hat Enterprise Linux 6 Reporter: Marian Krcmarik <mkrcmari>
Component: qemu-kvmAssignee: David Blechter <dblechte>
Status: CLOSED DUPLICATE QA Contact: Virtualization Bugs <virt-bugs>
Severity: high Docs Contact:
Priority: unspecified    
Version: 6.2CC: juzhang, lcapitulino, mkenneth, qzhang, shuang, tburke, virt-maint
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-08-26 14:04:40 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Marian Krcmarik 2011-08-11 16:33:09 UTC
Description of problem
Libvirt sometimes complains about getting Invalid string in json text from Qemu Monitor on SPICE_DISCONNECTED event.
For the exact message, please see attachment where I attached several examples of such message.
it's noticeable when using many VM through RHEVM, after disconnecting spice client from VM. Once one wanna try to connect again, User Portal complains about: "Unexpected exception", vdsm complains about libvirt error, and libvirt complains about wrong json text of  SPICE_DISCONNECTED event. Those messages are repeating in logs till the VM is shutdowned. Nothing interesting in qemu output (attaching as well).

Version-Release number of selected component (if applicable):
qemu-kvm-0.12.1.2-2.177
libvirt-0.9.4-0rc1.2
RHEVM (beta1 - ic136)
spice-server-0.8.2-3
Guest: Windows7x32 (with 3.0-14 guest tools), 30GB disk (thin provisioning), latest updates.

How reproducible:
It's (when you are trying long enough).

Steps to Reproduce:
1. Connect to a VM through RHEVM User Portal using spice client.
2. Disconnect from VM (close spice client).
3. Repeat Step 1. and 2. till User Portal prints Unexpected exception and does not open spice session.
  
Actual results:
UP: UNexcepted Exception.

VDSM: 
thread-154788::ERROR::2011-08-11 18:26:26,120::utils::369::vm.Vm::(collect) vmId=`8829251f-09f1-4dc6-a1a1-ec10dfa2f353`::Stats function failed: <AdvancedStatsFunction _highWrite at 0x1cd5880>
Traceback (most recent call last):
  File "/usr/share/vdsm/utils.py", line 366, in collect
    statsFunction()
  File "/usr/share/vdsm/utils.py", line 250, in __call__
    retValue = self._function(*args, **kwargs)
  File "/usr/share/vdsm/libvirtvm.py", line 65, in _highWrite
    self._vm._dom.blockInfo(vmDrive.path, 0)
  File "/usr/share/vdsm/libvirtvm.py", line 327, in f
    ret = attr(*args, **kwargs)
  File "/usr/share/vdsm/libvirtconnection.py", line 63, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1284, in blockInfo
    if ret is None: raise libvirtError ('virDomainGetBlockInfo() failed', dom=self)
libvirtError: internal error cannot parse json {"timestamp": {"seconds": 1313077093, "microseconds": 689265}, "event": "SPICE_DISCONNECTED", "data": {"server": {"port": "5900", "family": "ipv4", "host": "10.34.58.5"}, "client": {"port": "38645", "family":{"ip"timv4", ":ost": "10.34{29.89""se{"timestamp": {"seconds": 1313077093, "microseconds": 689265}, "event": "SPICE_DISCONNECTED", "data": {"server": {"port": "5900", "family": "ipv4", "host": "10.34.58.5"}, "client": {"port": "38645", "family":{"ip"timv4", ":ost": "10.34{29.89""seconds": 1313077093, "microseconds": 689245}, "event": "__com.redh{"timestamp": {"seconds":data": {"server": {"auth": "spice", "port": "5901", "family": "ipv4", "host": "10.34.58.5"}, "client": {"port": "35077", "family": "ipv4", "host": "10.34.29.89"}}}: lexical error: invalid string in json text.
          ort": "38645", "family":{"ip"timv4", ":ost": "10.34{29.89""s
                     (right here) ------^

Libvirt:
7034: debug : qemuMonitorSend:793 : Attempt to send command while error is set internal error cannot parse json {"timestamp": {"seconds": 1313077093, "microseconds": 689265}, "event": "SPICE_DISCONNECTED", "data": {"server": {"port": "5900", "family": "ipv4", "host": "10.34.58.5"}, "client": {"port": "38645", "family":{"ip"timv4", ":ost": "10.34{29.89""se{"timestamp": {"seconds": 1313077093, "microseconds": 689265}, "event": "SPICE_DISCONNECTED", "data": {"server": {"port": "5900", "family": "ipv4", "host": "10.34.58.5"}, "client": {"port": "38645", "family":{"ip"timv4", ":ost": "10.34{29.89""seconds": 1313077093, "microseconds": 689245}, "event": "__com.redh{"timestamp": {"seconds":data": {"server": {"auth": "spice", "port": "5901", "family": "ipv4", "host": "10.34.58.5"}, "client": {"port": "35077", "family": "ipv4", "host": "10.34.29.89"}}}: lexical error: invalid string in json text.
          ort": "38645", "family":{"ip"timv4", ":ost": "10.34{29.89""s
                     (right here) ------^

Expected results:
No error

Additional info:

Comment 3 Suqin Huang 2011-08-16 04:44:23 UTC
segment fault while I try to reproduce this bug, but no core file generated.

cmd: 
/usr/libexec/qemu-kvm -drive file=/usr/local/staf/test/RHEV/kvm-new/autotest/client/tests/kvm/images/RHEL-Server-6.1-64-virtio.raw,index=0,if=none,id=drive-virtio-disk1,media=disk,cache=none,format=raw,aio=native -device virtio-blk-pci,bus=pci.0,addr=0x4,drive=drive-virtio-disk1,id=virtio-disk1 -device virtio-net-pci,netdev=idoq0tcT,mac=9a:5e:b5:68:17:d8,id=ndev00idoq0tcT,bus=pci.0,addr=0x3 -netdev tap,id=idoq0tcT,vhost=on,ifname=t0-205512-G596,script=/usr/local/staf/test/RHEV/kvm-new/autotest/client/tests/kvm/scripts/qemu-ifup-switch,downscript=no -m 2048 -smp 2,cores=2,threads=1,sockets=1 -cpu Nehalem -rtc base=utc,clock=host,driftfix=none -M rhel6.2.0 -boot c -no-kvm-pit-reinjection -enable-kvm -monitor stdio -chardev socket,id=serial-rhel5,path=/tmp/serial-rhel5,server,nowait -device isa-serial,chardev=serial-rhel5 -vga qxl -spice port=8000,disable-ticketing -device virtio-serial -chardev spicevmc,id=vdagent,debug=0,name=vdagent -device virtserialport,chardev=vdagent,name=com.redhat.spice.0

Comment 4 Suqin Huang 2011-08-24 08:22:19 UTC
Add more info:

1. host

qemu-kvm-0.12.1.2-2.184.el6.x86_64
2.6.32-188.el6.x86_64
processor	: 3
vendor_id	: GenuineIntel
cpu family	: 6
model		: 23
model name	: Intel(R) Core(TM)2 Quad CPU    Q9400  @ 2.66GHz
stepping	: 10
cpu MHz		: 1998.000
cache size	: 3072 KB
physical id	: 0
siblings	: 4
core id		: 3
cpu cores	: 4
apicid		: 3
initial apicid	: 3
fpu		: yes
fpu_exception	: yes
cpuid level	: 13
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc arch_perfmon pebs bts rep_good aperfmperf pni dtes64 monitor ds_cpl vmx smx est tm2 ssse3 cx16 xtpr pdcm sse4_1 xsave lahf_lm dts tpr_shadow vnmi flexpriority
bogomips	: 5333.31
clflush size	: 64
cache_alignment	: 64
address sizes	: 36 bits physical, 48 bits virtual



2. result 
handle_dev_input: cursor disconnect
Segmentation fault (core dumped)

3. cmd
/usr/libexec/qemu-kvm -drive file='/home/RHEL-Server-6.1-64-virtio.qcow2',index=0,if=none,id=drive-virtio-disk1,media=disk,cache=none,format=qcow2,aio=native -device virtio-blk-pci,bus=pci.0,addr=0x4,drive=drive-virtio-disk1,id=virtio-disk1 -device virtio-net-pci,netdev=idJkKN3Y,mac=9a:d2:9c:3e:bc:a8,id=ndev00idJkKN3Y,bus=pci.0,addr=0x3 -netdev tap,id=idJkKN3Y,vhost=on,ifname='t0-133520-E44x',script='/home/Auto/autotest/client/tests/kvm/scripts/qemu-ifup-switch',downscript='no' -m 2048 -smp 4,cores=2,threads=1,sockets=2 -cpu Penryn -rtc base=utc,clock=host,driftfix=none -M rhel6.1.0 -boot order=cdn,once=n,menu=off   -usbdevice tablet -no-kvm-pit-reinjection -enable-kvm -spice port=8000,disable-ticketing -vga qxl -monitor stdio -qmp tcp:0:4444,server

Comment 5 Luiz Capitulino 2011-08-26 14:04:12 UTC
Suqin,

The segfault fault you describe might not be related to this bug. I suggest you open a separate bz to track it.

Comment 6 Luiz Capitulino 2011-08-26 14:04:40 UTC

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