Bug 823472

Created attachment 585777 [details]
virt-viewer debuginfo with --spice-debug option

While there may well be a virt-viewer bug causing this behaviour, IMHO, QEMU must be robust against a mis-behaving client. The VM certainly should never shutdown due to a badly written client.

Please can you provide the /var/log/libvirt/qemu/$GUESTNAME.log file for this guest so we can see if QEMU printed anything interesting.

Created attachment 585915 [details]
guest's log file

Thankyou, the guest log confirms there isa  spice-server bug here

red_channel_remove_client: ASSERT pthread_equal(pthread_self(), rcc->channel->thread_id) failed
red_channel_client_disconnect: 0x7fa93c0c3920 (channel 0x7fa93c045e90 type 4 id 0)
/usr/lib64/libspice-server.so.1(+0xbf485)[0x7fa99acd1485]
/usr/lib64/libspice-server.so.1(+0x1726e)[0x7fa99ac2926e]
/usr/lib64/libspice-server.so.1(+0x17369)[0x7fa99ac29369]
/usr/lib64/libspice-server.so.1(+0x451d0)[0x7fa99ac571d0]
/usr/lib64/libspice-server.so.1(+0x45c4e)[0x7fa99ac57c4e]
/usr/lib64/libspice-server.so.1(+0x45da0)[0x7fa99ac57da0]
/usr/libexec/qemu-kvm(+0x6219f)[0x7fa99ca8c19f]
/usr/libexec/qemu-kvm(+0x83a4a)[0x7fa99caada4a]
/usr/libexec/qemu-kvm(main+0x154c)[0x7fa99ca8ecec]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7fa99a404cdd]
/usr/libexec/qemu-kvm(+0x5ed09)[0x7fa99ca88d09]

This request was not resolved in time for the current release.
Red Hat invites you to ask your support representative to
propose this request, if still desired, for consideration in
the next release of Red Hat Enterprise Linux.

This request was erroneously removed from consideration in Red Hat Enterprise Linux 6.4, which is currently under development.  This request will be evaluated for inclusion in Red Hat Enterprise Linux 6.4.

(In reply to comment #0)
> Version-Release number of selected component (if applicable):
> virt-viewer-0.5.2-8.el6.x86_64
> libvirt-0.9.10-20.el6.x86_64
> virt-viewer-0.5.2-8.el6.x86_64
> qemu-kvm-0.12.1.2-2.294.el6.x86_64

What is spice-server version?
Can you please test with latest qemu-kvm and spice-server?
Can you provide a stacktrace with symbols and locals, particularly rcc->channel && rcc->channel->thread_id?

Thanks,
Alon

added needinfo from reporter according to Comment 9.

Too late for 6.4, moving to 6.5

(In reply to comment #9)
> (In reply to comment #0)
> > Version-Release number of selected component (if applicable):
> > virt-viewer-0.5.2-8.el6.x86_64
> > libvirt-0.9.10-20.el6.x86_64
> > virt-viewer-0.5.2-8.el6.x86_64
> > qemu-kvm-0.12.1.2-2.294.el6.x86_64
> 
> What is spice-server version?
> Can you please test with latest qemu-kvm and spice-server?
> Can you provide a stacktrace with symbols and locals, particularly
> rcc->channel && rcc->channel->thread_id?
> 
> Thanks,
> Alon

The issue still exists with the latest spice-server:
spice-server-0.12.0-1.el6.x86_64
qemu-kvm-0.12.1.2-2.316.el6.x86_64
libvirt-0.10.2-2.el6.x86_64
virt-viewer-0.5.2-13.el6.x86_64
virt-manager-0.9.0-15.el6.x86_64

Steps:
1.Use virt-manager to install a spice RHEL6 guest with audio device es1370.
2.Use virt-viewer to connect it
# virt-viewer --spice-debug demo1
3.Close virt-viewer,the guest shutdown.

It is really spice problem,after I open the console in virt-manager,the guest will shutdown a few minites later.

Created attachment 627955 [details]
virt-viewer debug info with --spice-debug option

Created attachment 627956 [details]
Log file from /var/log/libvirt/qemu/

--------------------------------------------------------------------------------
Problem description
--------------------------------------------------------------------------------

When starting a windows vm useing es1370 sound card like this:

/usr/libexec/qemu-kvm -enable-kvm win7-child.img -spice
port=5930,disable-ticketing -m 2048 -vga qxl -usbdevice tablet -device
ES1370,id=sound0,bus=pci.0,addr=0x3

use any spice client to connect this vm, the first time, the sound
channel may have not connected(the vm is still booting).

But after that, if the sound channel was connected,  disconnect to or
reboot the vm, the vm would crash.


The spice log shows:

red_channel_remove_client: ASSERT pthread_equal(pthread_self(),
rcc->channel->thread_id) failed


The gdb stack is :

#0  0x00007ffff4cb4885 in raise () from /lib64/libc.so.6
#1  0x00007ffff4cb6065 in abort () from /lib64/libc.so.6
#2  0x00007ffff54d3283 in ring_remove (rcc=0x7ffff9b25450) at
../common/ring.h:84
#3  red_channel_remove_client (rcc=0x7ffff9b25450) at red_channel.c:1183
#4  0x00007ffff54d5195 in red_channel_client_disconnect_dummy
(rcc=0x7ffff9b25450) at red_channel.c:1201
#5  red_channel_client_disconnect (rcc=0x7ffff9b25450) at red_channel.c:1212
#6  0x00007ffff55011fb in snd_disconnect_channel (channel=0x7ffff9b50010) at
snd_worker.c:222
#7  0x00007ffff5501c9e in snd_receive (data=0x7ffff9b50010) at snd_worker.c:475
#8  0x00007ffff5501df0 in snd_event (fd=<value optimized out>, event=<value
optimized out>, data=<value optimized out>)  at snd_worker.c:505
#9  0x00007ffff7deb76f in main_loop_wait (timeout=1000) at
/usr/src/debug/qemu-kvm-0.12.1.2/vl.c:3990
#10 0x00007ffff7e0d01a in kvm_main_loop () at
/usr/src/debug/qemu-kvm-0.12.1.2/qemu-kvm.c:2244
#11 0x00007ffff7dee2bc in main_loop (argc=20, argv=<value optimized out>,
envp=<value optimized out>) at /usr/src/debug/qemu-kvm-0.12.1.2/vl.c:4202
#12 main (argc=20, argv=<value optimized out>, envp=<value optimized out>) at
/usr/src/debug/qemu-kvm-0.12.1.2/vl.c:6427


Yes, the red_channel_remove_client calls:

ASSERT( pthread_equal(pthread_self(), rcc->channel->thread_id) )



--------------------------------------------------------------------------------
Problem analysis
--------------------------------------------------------------------------------

I found that the channel type is 6, created in snd_attach_record.

red_channel_create_dummy(sizeof(RedChannel), SPICE_CHANNEL_RECORD, 0)


In my running session, snd_attach_record is called in the thread  11 :

12 Thread 0x7fff339fc700 (LWP 8213)  0x00007ffff54ca3ed in glz_rgb32_do_match
(encoder=0x7fffc008ac00, seg_idx=7,     from=<value optimized out>,
copied=<value optimized out>) at glz_encode_tmpl.c:234

* 11 Thread 0x7fffcdbf5700 (LWP 8204)  red_channel_create_dummy (size=320,
type=6, id=0) at red_channel.c:676

  10 Thread 0x7fffce5f6700 (LWP 8203)  0x00007ffff7750ff4 in __lll_lock_wait ()
from /lib64/libpthread.so.0
 ......

  1 Thread 0x7ffff7d64940 (LWP 8036)  0x00007ffff7750ff4 in __lll_lock_wait ()
from /lib64/libpthread.so.0


The gdb call stack is :

#0  red_channel_create_dummy (size=<value optimized out>, type=6, id=0) at
red_channel.c:695
#1  0x00007ffff5501449 in snd_attach_record (sin=0x7fffbc00a0a0) at
snd_worker.c:1503
#2  0x00007ffff54f4f3e in spice_server_add_interface (s=<value optimized out>,
sin=0x7fffbc00a0a0) at reds.c:3460
#3  0x00007ffff7e7fd88 in line_in_init (hw=0x7fffbc00a030, as=<value optimized
out>) at audio/spiceaudio.c:226
#4  0x00007ffff7e7c466 in audio_pcm_hw_add_new_in (as=0x7fffcdbf49e0) at
audio/audio_template.h:274
#5  0x00007ffff7e7ca9a in audio_pcm_hw_add_in (card=0x7ffff9175280, sw=<value
optimized out>, name=0x7ffff7faf5f0 "es1370.adc",
callback_opaque=0x7ffff9175010,
callback_fn=0x7ffff7f3db20<es1370_adc_callback>, as=0x7fffcdbf4a70)
at audio/audio_template.h:316
#6  audio_pcm_create_voice_pair_in (card=0x7ffff9175280, sw=<value
optimized out>, name=0x7ffff7faf5f0 "es1370.adc",
callback_opaque=0x7ffff9175010, callback_fn=0x7ffff7f3db20
<es1370_adc_callback>, as=0x7fffcdbf4a70) at
audio/audio_template.h:358
#7  AUD_open_in (card=0x7ffff9175280, sw=<value optimized out>,
name=0x7ffff7faf5f0 "es1370.adc", callback_opaque=0x7ffff9175010,
callback_fn=0x7ffff7f3db20 <es1370_adc_callback>, as=0x7fffcdbf4a70)
at audio/audio_template.h:481
#8  0x00007ffff7f3d607 in es1370_update_voices (s=0x7ffff9175038,
ctl=671088641, sctl=0) at /usr/src/debug/qemu-kvm-0.12.1.2/hw/es1370.c:427
#9  0x00007ffff7e0eeb5 in kvm_handle_io (env=0x7ffff90a2010) at
/usr/src/debug/qemu-kvm-0.12.1.2/kvm-all.c:587
#10 kvm_run (env=0x7ffff90a2010) at
/usr/src/debug/qemu-kvm-0.12.1.2/qemu-kvm.c:1048
#11 0x00007ffff7e0ef69 in kvm_cpu_exec (env=<value optimized out>) at
/usr/src/debug/qemu-kvm-0.12.1.2/qemu-kvm.c:1743
#12 0x00007ffff7e0fe4d in kvm_main_loop_cpu (_env=0x7ffff90a2010) at
/usr/src/debug/qemu-kvm-0.12.1.2/qemu-kvm.c:2004
#13 ap_main_loop (_env=0x7ffff90a2010) at
/usr/src/debug/qemu-kvm-0.12.1.2/qemu-kvm.c:2060
#14 0x00007ffff774a7f1 in start_thread () from /lib64/libpthread.so.0
#15 0x00007ffff4d6770d in clone () from /lib64/libc.so.6


But when calling the snd_disconnect_channel, the thread is 1:

12 Thread 0x7fff339fc700 (LWP 8213)  0x00007ffff4d67d03 in epoll_wait () from
/lib64/libc.so.6
  11 Thread 0x7fffcdbf5700 (LWP 8204)  0x00007ffff7750ff4 in __lll_lock_wait ()
from /lib64/libpthread.so.0
......
  2 Thread 0x7fffef78a700 (LWP 8096)  0x00007ffff774e75b in
pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
* 1 Thread 0x7ffff7d64940 (LWP 8036)  0x00007ffff4cb4885 in raise () from
/lib64/libc.so.6



So, it is obviously that thread id of creating and destroying
SPICE_CHANNEL_RECORD channel is not equal.


--------------------------------------------------------------------------------
Patch
--------------------------------------------------------------------------------

diff --git a/server/red_channel.c b/server/red_channel.c
index b52f9e6..1ca845f 100644
--- a/server/red_channel.c
+++ b/server/red_channel.c
@@ -1424,6 +1424,14 @@ static void red_channel_remove_client(RedChannelClient *rcc)
     // TODO: should we set rcc->channel to NULL???
 }
 
+static void red_channel_remove_client_dummy(RedChannelClient *rcc)
+{
+    ring_remove(&rcc->channel_link);
+    spice_assert(rcc->channel->clients_num > 0);
+    rcc->channel->clients_num--;
+    // TODO: should we set rcc->channel to NULL???
+}
+
 static void red_client_remove_channel(RedChannelClient *rcc)
 {
     pthread_mutex_lock(&rcc->client->lock);
@@ -1436,7 +1444,7 @@ static void red_channel_client_disconnect_dummy(RedChannelClient *rcc)
 {
     spice_assert(rcc->dummy);
     if (ring_item_is_linked(&rcc->channel_link)) {
-        red_channel_remove_client(rcc);
+        red_channel_remove_client_dummy(rcc);
     }
     rcc->dummy_connected = FALSE;
 }
[xufang@rhel-station]$ vim /home/xufang/rpmbuild/
BUILD/     BUILDROOT/ RPMS/      SOURCES/   SPECS/     SRPMS/     
[xufang@rhel-station]$ cat /home/xufang/rpmbuild/SOURCES/0029-cs2c-spice-server-red_channel_remove_client.patch 
diff --git a/server/red_channel.c b/server/red_channel.c
index 6296dc9..e401cfb 100644
--- a/server/red_channel.c
+++ b/server/red_channel.c
@@ -1131,7 +1131,11 @@ void red_channel_pipes_add_type(RedChannel *channel, int pipe_item_type)
 
 int red_channel_client_is_connected(RedChannelClient *rcc)
 {
-    return rcc->stream != NULL;
+    if (!rcc->dummy) {                                                                                          
+      return rcc->stream != NULL;
+    } else {
+      return rcc->dummy_connected;
+    }
 }
 
 int red_channel_is_connected(RedChannel *channel)
@@ -1182,6 +1186,13 @@ static void red_channel_remove_client(RedChannelClient *rcc)
     // TODO: should we set rcc->channel to NULL???
 }
 
+static void red_channel_remove_client_dummy(RedChannelClient *rcc)
+{
+    ring_remove(&rcc->channel_link);
+    ASSERT(rcc->channel->clients_num > 0);
+    rcc->channel->clients_num--;
+}
+
 static void red_client_remove_channel(RedChannelClient *rcc)
 {
     pthread_mutex_lock(&rcc->client->lock);
@@ -1190,10 +1201,25 @@ static void red_client_remove_channel(RedChannelClient *rcc)
     pthread_mutex_unlock(&rcc->client->lock);
 }
 
+static void red_channel_client_disconnect_dummy(RedChannelClient *rcc)                                                                
+{
+      ASSERT(rcc->dummy);
+      if (ring_item_is_linked(&rcc->channel_link)) {
+        red_channel_remove_client_dummy(rcc);
+      }
+      rcc->dummy_connected = FALSE;
+}
+
+
 void red_channel_client_disconnect(RedChannelClient *rcc)
 {
-    red_printf("%p (channel %p type %d id %d)", rcc, rcc->channel,
-                                                rcc->channel->type, rcc->channel->id);
+    //red_printf("%p (channel %p type %d id %d)", rcc, rcc->channel,
+    //           rcc->channel->type, rcc->channel->id);
+    if (rcc->dummy) {
+        red_channel_client_disconnect_dummy(rcc);
+        return;
+    }
+
     if (!red_channel_client_is_connected(rcc)) {
         return;
     }
@@ -1243,6 +1269,9 @@ RedChannelClient *red_channel_client_create_dummy(int size,
     rcc->incoming.header.data = rcc->incoming.header_buf;
     rcc->incoming.serial = 1;
 
+    rcc->dummy = TRUE;
+    rcc->dummy_connected = TRUE;
+
     red_channel_add_client(channel, rcc);
     return rcc;
 }
diff --git a/server/red_channel.h b/server/red_channel.h
index 543aec1..efef777 100644
--- a/server/red_channel.h
+++ b/server/red_channel.h
@@ -219,6 +219,10 @@ struct RedChannelClient {
     RedChannel *channel;
     RedClient  *client;
     RedsStream *stream;
+
+    int dummy;
+    int dummy_connected;
+
     struct {
         uint32_t generation;
         uint32_t client_generation;
diff --git a/server/snd_worker.c b/server/snd_worker.c
index e78d1d3..f924bc3 100644
--- a/server/snd_worker.c
+++ b/server/snd_worker.c
@@ -202,9 +202,8 @@ static SndChannel *snd_channel_get(SndChannel *channel)
 static SndChannel *snd_channel_put(SndChannel *channel)
 {
     if (!--channel->refs) {
-        channel->worker->connection = NULL;
         free(channel);
-        red_printf("sound channel freed\n");
+        //red_printf("sound channel freed\n");
         return NULL;
     }
     return channel;
@@ -217,14 +216,18 @@ static void snd_disconnect_channel(SndChannel *channel)
     if (!channel) {
         return;
     }
-    channel->cleanup(channel);
     worker = channel->worker;
-    red_channel_client_destroy_dummy(worker->connection->channel_client);
-    core->watch_remove(channel->stream->watch);
-    channel->stream->watch = NULL;
-    reds_stream_free(channel->stream);
-    spice_marshaller_destroy(channel->send_data.marshaller);
+    if (channel->stream) {
+        channel->cleanup(channel);
+        red_channel_client_disconnect(worker->connection->channel_client);
+        core->watch_remove(channel->stream->watch);
+        channel->stream->watch = NULL;
+        reds_stream_free(channel->stream);
+        channel->stream = NULL;
+        spice_marshaller_destroy(channel->send_data.marshaller);
+    }
     snd_channel_put(channel);
+    worker->connection = NULL;
 }
 
 static void snd_playback_free_frame(PlaybackChannel *playback_channel, AudioFrame *frame)
@@ -989,9 +992,11 @@ static void snd_disconnect_channel_client(RedChannelClient *rcc)
     ASSERT(rcc->channel->data);
     worker = (SndWorker *)rcc->channel->data;
 
-    ASSERT(worker->connection->channel_client == rcc);
-    snd_disconnect_channel(worker->connection);
-    ASSERT(worker->connection == NULL);
+    if (worker->connection) {
+        ASSERT(worker->connection->channel_client == rcc);
+        snd_disconnect_channel(worker->connection);
+    }
+
 }
 
 static void snd_set_command(SndChannel *channel, uint32_t command)

see also :

https://bugzilla.redhat.com/show_bug.cgi?id=759847#c12

The patch was based on spice-server-0.10.1-10.el6.x86_64

diff --git a/server/red_channel.c b/server/red_channel.c
index 6296dc9..e401cfb 100644
--- a/server/red_channel.c
+++ b/server/red_channel.c
@@ -1131,7 +1131,11 @@ void red_channel_pipes_add_type(RedChannel *channel, int pipe_item_type)
 
 int red_channel_client_is_connected(RedChannelClient *rcc)
 {
-    return rcc->stream != NULL;
+    if (!rcc->dummy) {                                                                                          
+      return rcc->stream != NULL;
+    } else {
+      return rcc->dummy_connected;
+    }
 }
 
 int red_channel_is_connected(RedChannel *channel)
@@ -1182,6 +1186,13 @@ static void red_channel_remove_client(RedChannelClient *rcc)
     // TODO: should we set rcc->channel to NULL???
 }
 
+static void red_channel_remove_client_dummy(RedChannelClient *rcc)
+{
+    ring_remove(&rcc->channel_link);
+    ASSERT(rcc->channel->clients_num > 0);
+    rcc->channel->clients_num--;
+}
+
 static void red_client_remove_channel(RedChannelClient *rcc)
 {
     pthread_mutex_lock(&rcc->client->lock);
@@ -1190,10 +1201,25 @@ static void red_client_remove_channel(RedChannelClient *rcc)
     pthread_mutex_unlock(&rcc->client->lock);
 }
 
+static void red_channel_client_disconnect_dummy(RedChannelClient *rcc)                                                                
+{
+      ASSERT(rcc->dummy);
+      if (ring_item_is_linked(&rcc->channel_link)) {
+        red_channel_remove_client_dummy(rcc);
+      }
+      rcc->dummy_connected = FALSE;
+}
+
+
 void red_channel_client_disconnect(RedChannelClient *rcc)
 {
-    red_printf("%p (channel %p type %d id %d)", rcc, rcc->channel,
-                                                rcc->channel->type, rcc->channel->id);
+    //red_printf("%p (channel %p type %d id %d)", rcc, rcc->channel,
+    //           rcc->channel->type, rcc->channel->id);
+    if (rcc->dummy) {
+        red_channel_client_disconnect_dummy(rcc);
+        return;
+    }
+
     if (!red_channel_client_is_connected(rcc)) {
         return;
     }
@@ -1243,6 +1269,9 @@ RedChannelClient *red_channel_client_create_dummy(int size,
     rcc->incoming.header.data = rcc->incoming.header_buf;
     rcc->incoming.serial = 1;
 
+    rcc->dummy = TRUE;
+    rcc->dummy_connected = TRUE;
+
     red_channel_add_client(channel, rcc);
     return rcc;
 }
diff --git a/server/red_channel.h b/server/red_channel.h
index 543aec1..efef777 100644
--- a/server/red_channel.h
+++ b/server/red_channel.h
@@ -219,6 +219,10 @@ struct RedChannelClient {
     RedChannel *channel;
     RedClient  *client;
     RedsStream *stream;
+
+    int dummy;
+    int dummy_connected;
+
     struct {
         uint32_t generation;
         uint32_t client_generation;
diff --git a/server/snd_worker.c b/server/snd_worker.c
index e78d1d3..f924bc3 100644
--- a/server/snd_worker.c
+++ b/server/snd_worker.c
@@ -202,9 +202,8 @@ static SndChannel *snd_channel_get(SndChannel *channel)
 static SndChannel *snd_channel_put(SndChannel *channel)
 {
     if (!--channel->refs) {
-        channel->worker->connection = NULL;
         free(channel);
-        red_printf("sound channel freed\n");
+        //red_printf("sound channel freed\n");
         return NULL;
     }
     return channel;
@@ -217,14 +216,18 @@ static void snd_disconnect_channel(SndChannel *channel)
     if (!channel) {
         return;
     }
-    channel->cleanup(channel);
     worker = channel->worker;
-    red_channel_client_destroy_dummy(worker->connection->channel_client);
-    core->watch_remove(channel->stream->watch);
-    channel->stream->watch = NULL;
-    reds_stream_free(channel->stream);
-    spice_marshaller_destroy(channel->send_data.marshaller);
+    if (channel->stream) {
+        channel->cleanup(channel);
+        red_channel_client_disconnect(worker->connection->channel_client);
+        core->watch_remove(channel->stream->watch);
+        channel->stream->watch = NULL;
+        reds_stream_free(channel->stream);
+        channel->stream = NULL;
+        spice_marshaller_destroy(channel->send_data.marshaller);
+    }
     snd_channel_put(channel);
+    worker->connection = NULL;
 }
 
 static void snd_playback_free_frame(PlaybackChannel *playback_channel, AudioFrame *frame)
@@ -989,9 +992,11 @@ static void snd_disconnect_channel_client(RedChannelClient *rcc)
     ASSERT(rcc->channel->data);
     worker = (SndWorker *)rcc->channel->data;
 
-    ASSERT(worker->connection->channel_client == rcc);
-    snd_disconnect_channel(worker->connection);
-    ASSERT(worker->connection == NULL);
+    if (worker->connection) {
+        ASSERT(worker->connection->channel_client == rcc);
+        snd_disconnect_channel(worker->connection);
+    }
+
 }
 
 static void snd_set_command(SndChannel *channel, uint32_t command)

spice-server assumes that all the calls to its interface are done from qemu main thread. It is a common assumption to all the interfaces and not just the audio one.
However, with es1370 device, the calls to the sound interface are done from kvm_main_loop_cpu. With intel-hda, we don't have such problem. I don't know if it is a qemu bug or a feature.
Gerd, can you comment on this?

(In reply to Yonit Halperin from comment #19)
> spice-server assumes that all the calls to its interface are done from qemu
> main thread. It is a common assumption to all the interfaces and not just
> the audio one.
> However, with es1370 device, the calls to the sound interface are done from
> kvm_main_loop_cpu. With intel-hda, we don't have such problem. I don't know
> if it is a qemu bug or a feature.
> Gerd, can you comment on this?

After some more examination and discussions with alon, I need to correct myself:
spice interface can be called from both the io thread and the vcpu thread, in most cases this is not a problem, since qemu use a global mutex.
So, if a channel was created in the vcpu thread, but it is destroyed from the iothread, we shouldn't assert.

posted a patch: http://patchwork.freedesktop.org/patch/13731/

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, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2013-1571.html