Created attachment 892857 [details] remote-viewer debug log. Description of problem: I believed that was a network connection problem or problem of particular setup earlier but now I can reproduce on two different setups. It seems that some channels get somehow disconnected after some time of idling spice session. It's visible especially with inputs which are not passed to the guest. I am attaching spice debug of remote-viewer, there are visible msgs that inputs were refused due to closed channel at the end of the log. If I do "info spice" monitor command on the qemu instance I can see all channels to be reported as connected (I assume) instead of channel 5 (playback) Channel: address: 10.36.6.93:51805 [tls] session: 880712647 channel: 1:0 Channel: address: 10.36.6.93:51809 [tls] session: 880712647 channel: 9:3 Channel: address: 10.36.6.93:51812 [tls] session: 880712647 channel: 9:0 Channel: address: 10.36.6.93:51815 [tls] session: 880712647 channel: 2:3 Channel: address: 10.36.6.93:51818 [tls] session: 880712647 channel: 2:0 Channel: address: 10.36.6.93:51817 [tls] session: 880712647 channel: 2:1 Channel: address: 10.36.6.93:51816 [tls] session: 880712647 channel: 2:2 Channel: address: 10.36.6.93:51814 [tls] session: 880712647 channel: 6:0 Channel: address: 10.36.6.93:51811 [tls] session: 880712647 channel: 9:1 Channel: address: 10.36.6.93:51810 [tls] session: 880712647 channel: 9:2 Channel: address: 10.36.6.93:51822 [tls] session: 880712647 channel: 4:3 Channel: address: 10.36.6.93:51820 [tls] session: 880712647 channel: 3:0 Channel: address: 10.36.6.93:51823 [tls] session: 880712647 channel: 4:1 Channel: address: 10.36.6.93:51821 [tls] session: 880712647 channel: 8:0 Channel: address: 10.36.6.93:51824 [tls] session: 880712647 channel: 4:2 Channel: address: 10.36.6.93:51825 [tls] session: 880712647 channel: 4:0 There is even a mention in qemu log about that: ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 62 snd_channel_put: SndChannel=0x7f36077e44c0 freed ((null):26775): Spice-Info **: snd_worker.c:1107:spice_server_playback_put_samples: audio samples belong to a disconnected channel But If I do netstat for established connection on the client I can see only these: tcp 0 0 10.36.6.93:51817 10.34.73.134:5901 ESTABLISHED 18471/remote-viewer tcp 0 74 10.36.6.93:51818 10.34.73.134:5901 ESTABLISHED 18471/remote-viewer tcp 0 0 10.36.6.93:51815 10.34.73.134:5901 ESTABLISHED 18471/remote-viewer tcp 0 0 10.36.6.93:51805 10.34.73.134:5901 ESTABLISHED 18471/remote-viewer tcp 0 0 10.36.6.93:51816 10.34.73.134:5901 ESTABLISHED 18471/remote-viewer which is only main and display channel. I can reproduce on F20 client, RHEL6.5 and Windows 3.4 as well. Version-Release number of selected component (if applicable): client: Windows 7 0.5.623 minw=gw-virt-viewer or F20 spice-gtk-0.23-2.fc20.x86_64 or RHEL6.5 spice-gtk-0.20-11.el6_5.1 Server: rpm -qa | egrep "spice|qemu" qemu-kvm-rhev-0.12.1.2-2.415.el6_5.9.x86_64 gpxe-roms-qemu-0.9.7-6.10.el6.noarch qemu-kvm-rhev-tools-0.12.1.2-2.415.el6_5.9.x86_64 qemu-kvm-rhev-debuginfo-0.12.1.2-2.415.el6_5.9.x86_64 spice-server-debuginfo-0.12.4-6.el6_5.1.x86_64 spice-server-0.12.4-6.el6_5.1.x86_64 qemu-img-rhev-0.12.1.2-2.415.el6_5.9.x86_64 How reproducible: Often Steps to Reproduce: 1. Open a spice session and let it idle. Actual results: Some channels seem to be closed so inputs are not passed to the VM, or playback does not work, but display seems to be fine. Expected results: Smooth operation Additional info:
x channels debug message: Closing the connection: spice_channel_read() - ret=0 Since this is SSL connections, man SSL_read: 0 The read operation was not successful. The reason may either be a clean shutdown due to a "close notify" alert sent by the peer (in which case the SSL_RECEIVED_SHUTDOWN flag in the ssl shutdown state is set (see SSL_shutdown(3), SSL_set_shutdown(3)). It is also possible, that the peer simply shut down the underlying transport and the shutdown is incomplete. Call SSL_get_error() with the return value ret to find out, whether an error occurred or the connection was shut down cleanly (SSL_ERROR_ZERO_RETURN). When it happens, can you provide server log & server netstat? Sadly I don't see an easy way to add debugging to openssl. Could you check this also happen without ssl? thanks
So now only main and display channels reported to be connected by qemu: Server: migrated: false address: 10.34.73.134:5900 address: 10.34.73.134:5901 [tls] auth: spice Channel: address: 10.34.73.1:51933 [tls] session: 2037382744 channel: 1:0 Channel: address: 10.34.73.1:51942 [tls] session: 2037382744 channel: 2:1 Channel: address: 10.34.73.1:51941 [tls] session: 2037382744 channel: 2:2 Channel: address: 10.34.73.1:51940 [tls] session: 2037382744 channel: 2:3 Channel: address: 10.34.73.1:51943 [tls] session: 2037382744 channel: 2:0 and netstat on the server show only these connections as well: tcp 0 0 10.34.73.134:5901 10.34.73.1:51933 ESTABLISHED 26775/qemu-kvm tcp 0 0 10.34.73.134:5901 10.34.73.1:51940 ESTABLISHED 26775/qemu-kvm tcp 0 0 10.34.73.134:5901 10.34.73.1:51942 ESTABLISHED 26775/qemu-kvm tcp 0 0 10.34.73.134:5901 10.34.73.1:51943 ESTABLISHED 26775/qemu-kvm tcp 0 0 10.34.73.134:5901 10.34.73.1:51941 ESTABLISHED 26775/qemu-kvm Spice server info log (could get possibly debug): ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 1:0, connected successfully, over Secure link main_channel_link: add main channel client ((null):26775): Spice-Info **: reds.c:1700:reds_handle_main_link: NEW Client 0x7f3607e73e70 mcc 0x7f3607995000 connect-id 2037382744 ((null):26775): SpiceWorker-Info **: red_worker.c:11874:handle_dev_set_mouse_mode: mouse mode 2 ((null):26775): SpiceWorker-Info **: red_worker.c:11874:handle_dev_set_mouse_mode: mouse mode 2 ((null):26775): SpiceWorker-Info **: red_worker.c:11874:handle_dev_set_mouse_mode: mouse mode 2 ((null):26775): SpiceWorker-Info **: red_worker.c:11874:handle_dev_set_mouse_mode: mouse mode 2 main_channel_handle_parsed: agent start main_channel_handle_parsed: net test: latency 8.387000 ms, bitrate 216124947 bps (206.112811 Mbps) ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 2:1, connected successfully, over Secure link ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 2:2, connected successfully, over Secure link ((null):26775): SpiceWorker-Info **: red_worker.c:11693:handle_dev_display_connect: connect ((null):26775): SpiceWorker-Info **: red_worker.c:10785:handle_new_display_channel: add display channel client ((null):26775): SpiceWorker-Info **: red_worker.c:10793:handle_new_display_channel: New display (client 0x7f3607e73e70) dcc 0x7f359821fec0 stream 0x7f3607b53e10 ((null):26775): SpiceWorker-Info **: red_worker.c:10820:handle_new_display_channel: jpeg disabled ((null):26775): SpiceWorker-Info **: red_worker.c:10821:handle_new_display_channel: zlib-over-glz disabled ((null):26775): SpiceWorker-Info **: red_worker.c:11693:handle_dev_display_connect: connect ((null):26775): SpiceWorker-Info **: red_worker.c:10785:handle_new_display_channel: add display channel client ((null):26775): SpiceWorker-Info **: red_worker.c:10793:handle_new_display_channel: New display (client 0x7f3607e73e70) dcc 0x7f358c21fec0 stream 0x7f36085b0110 ((null):26775): SpiceWorker-Info **: red_worker.c:10820:handle_new_display_channel: jpeg disabled ((null):26775): SpiceWorker-Info **: red_worker.c:10821:handle_new_display_channel: zlib-over-glz disabled ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 2:3, connected successfully, over Secure link ((null):26775): SpiceWorker-Info **: red_worker.c:11693:handle_dev_display_connect: connect ((null):26775): SpiceWorker-Info **: red_worker.c:10785:handle_new_display_channel: add display channel client ((null):26775): SpiceWorker-Info **: red_worker.c:10793:handle_new_display_channel: New display (client 0x7f3607e73e70) dcc 0x7f358021fec0 stream 0x7f36079641b0 ((null):26775): SpiceWorker-Info **: red_worker.c:10820:handle_new_display_channel: jpeg disabled ((null):26775): SpiceWorker-Info **: red_worker.c:10821:handle_new_display_channel: zlib-over-glz disabled ((null):26775): SpiceWorker-Info **: red_worker.c:9821:display_channel_client_wait_for_init: creating encoder with id == 1 ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 5:0, connected successfully, over Secure link ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 9:1, connected successfully, over Secure link ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 9:0, connected successfully, over Secure link ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 9:2, connected successfully, over Secure link ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 2:0, connected successfully, over Secure link ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): SpiceWorker-Info **: red_worker.c:11693:handle_dev_display_connect: connect((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 9:3, connected successfully, over Secure link ((null):26775): SpiceWorker-Info **: red_worker.c:10785:handle_new_display_channel: add display channel client ((null):26775): SpiceWorker-Info **: red_worker.c:10793:handle_new_display_channel: New display (client 0x7f3607e73e70) dcc 0x7f35a4349d30 stream 0x7f3607e46d90 ((null):26775): SpiceWorker-Info **: red_worker.c:10820:handle_new_display_channel: jpeg disabled ((null):26775): SpiceWorker-Info **: red_worker.c:10821:handle_new_display_channel: zlib-over-glz disabled ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 6:0, connected successfully, over Secure link ((null):26775): SpiceWorker-Info **: red_worker.c:9821:display_channel_client_wait_for_init: creating encoder with id == 2 ((null):26775): SpiceWorker-Info **: red_worker.c:9821:display_channel_client_wait_for_init: creating encoder with id == 3 ((null):26775): SpiceWorker-Info **: red_worker.c:9821:display_channel_client_wait_for_init: creating encoder with id == 0 ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 4:1, connected successfully, over Secure link red_dispatcher_set_cursor_peer: ((null):26775): SpiceWorker-Info **: red_worker.c:11776:handle_dev_cursor_connect: cursor connect ((null):26775): SpiceWorker-Info **: red_worker.c:10967:red_connect_cursor: add cursor channel client ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 3:0, connected successfully, over Secure link inputs_connect: inputs channel client create ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 8:0, connected successfully, over Secure link ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 4:2, connected successfully, over Secure link red_dispatcher_set_cursor_peer: ((null):26775): SpiceWorker-Info **: red_worker.c:11776:handle_dev_cursor_connect: cursor connect ((null):26775): SpiceWorker-Info **: red_worker.c:10967:red_connect_cursor: add cursor channel client ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 4:3, connected successfully, over Secure link red_dispatcher_set_cursor_peer: ((null):26775): SpiceWorker-Info **: red_worker.c:11776:handle_dev_cursor_connect: cursor connect ((null):26775): SpiceWorker-Info **: red_worker.c:10967:red_connect_cursor: add cursor channel client ((null):26775): Spice-Info **: reds.c:2664:reds_handle_auth_mechanism: Auth method: 1 ((null):26775): Spice-Info **: reds.c:1531:reds_info_new_channel: channel 4:0, connected successfully, over Secure link red_dispatcher_set_cursor_peer: ((null):26775): SpiceWorker-Info **: red_worker.c:11776:handle_dev_cursor_connect: cursor connect ((null):26775): SpiceWorker-Info **: red_worker.c:10967:red_connect_cursor: add cursor channel client red_channel_client_disconnect_dummy: rcc=0x7f3607968ac0 (channel=0x7f3607b211e0 type=5 id=0) ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 59 snd_channel_put: SndChannel=0x7f36077e44c0 freed red_channel_client_disconnect: rcc=0x7f3607954800 (channel=0x7f3607b21e20 type=9 id=1) ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 58 red_channel_client_disconnect: rcc=0x7f36079a5200 (channel=0x7f3607b264a0 type=9 id=2) ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 56 red_channel_client_disconnect: rcc=0x7f36077d0200 (channel=0x7f3607b26ad0 type=9 id=3) ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 55 red_channel_client_disconnect_dummy: rcc=0x7f3607a66810 (channel=0x7f3607b21430 type=6 id=0) ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 60 snd_channel_put: SndChannel=0x7f360a3c3d40 freed red_channel_client_disconnect: rcc=0x7f3607810a00 (channel=0x7f3607b217d0 type=9 id=0) ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 57 red_channel_client_disconnect: rcc=0x7f36080d6590 (channel=0x7f360801e6c0 type=8 id=0) red_channel_client_disconnect: rcc=0x7f3598a7d250 (channel=0x7f359821f920 type=4 id=1) ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 67 red_channel_client_disconnect: rcc=0x7f358c26f4a0 (channel=0x7f358c21f920 type=4 id=2) red_channel_client_disconnect: rcc=0x7f358026f4a0 (channel=0x7f358021f920 type=4 id=3) ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 68 ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 69 ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 66 red_channel_client_disconnect: rcc=0x7f3607a2a2c0 (channel=0x7f3607aa1d00 type=3 id=0) ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 65 red_channel_client_disconnect: rcc=0x7f35a42ea6a0 (channel=0x7f35a421f920 type=4 id=0) ((null):26775): Spice-Info **: reds.c:4644:reds_stream_free: close socket fd 70
you are still using tls, could you try without it?
(In reply to Marc-Andre Lureau from comment #4) > you are still using tls, could you try without it? I can still observe it without ssl: Server: migrated: false address: 10.34.73.134:5900 address: 10.34.73.134:5901 [tls] auth: spice Channel: address: 10.34.73.1:59572 session: 921178357 channel: 1:0 Channel: address: 10.34.73.1:59581 session: 921178357 channel: 2:3 Channel: address: 10.34.73.1:59579 session: 921178357 channel: 2:2 Channel: address: 10.34.73.1:59577 session: 921178357 channel: 2:1 Channel: address: 10.34.73.1:59574 session: 921178357 channel: 2:0 Only main and inputs channel again. tcp 0 0 10.34.73.134:5900 10.34.73.1:59579 ESTABLISHED 15779/qemu-kvm tcp 0 0 10.34.73.134:5900 10.34.73.1:59572 ESTABLISHED 15779/qemu-kvm tcp 0 0 10.34.73.134:5900 10.34.73.1:59574 ESTABLISHED 15779/qemu-kvm tcp 0 0 10.34.73.134:5900 10.34.73.1:59581 ESTABLISHED 15779/qemu-kvm tcp 0 0 10.34.73.134:5900 10.34.73.1:59577 ESTABLISHED 15779/qemu-kvm
(In reply to Marian Krcmarik from comment #3) > Spice server info log (could get possibly debug): yes please :)
I am quite sad to imagine that this could be a day 0 bug... diff --git a/server/red_channel.c b/server/red_channel.c index 4f85365..995195c 100644 --- a/server/red_channel.c +++ b/server/red_channel.c @@ -210,7 +210,7 @@ static int red_peer_receive(RedsStream *stream, uint8_t *buf, uint32_t size) } spice_assert(now == -1); if (errno == EAGAIN) { - break; + continue; } else if (errno == EINTR) { continue; } else if (errno == EPIPE) { if EAGAIN is received when 0 bytes have been read, the channel will be disconnected.
Not so fast, it seems the red_peer_receive() calls returning 0 should not disconnect (argh, not following conventions)
Marian, is this the squid proxy idle bug? that looks like it
(In reply to Marc-Andre Lureau from comment #10) > Marian, is this the squid proxy idle bug? that looks like it I am still looking at it, i will update bug soon with more details, but I can say I do not observe it only when connecting through proxy.
(In reply to Marian Krcmarik from comment #11) > (In reply to Marc-Andre Lureau from comment #10) > > Marian, is this the squid proxy idle bug? that looks like it > > I am still looking at it, i will update bug soon with more details, but I > can say I do not observe it only when connecting through proxy. ok, it could be client main channel somehow "frozen" (similarly to clipboard issue). Try to get the client log & backtrace when it happens.
Marian, could you give some update? shouldn't severity be lowered?
moving to 6.7, waiting for Marian comments. "idle" bugs are pretty much all network related issue so far, since Spice already uses tcp keepalive.
(In reply to Marc-Andre Lureau from comment #13) > Marian, could you give some update? shouldn't severity be lowered? Probably It seems to be related to the timeouts for idling connections (connections with no data transfer) - I can see the problem when using Squid in default mode - 15mins timetout for connections without data transfer or even when connection over vpnc 2 hours timeout seems to be default value for vpnc. IT confused me since I could reproduce it even without Proxy but I relized It was over vpnc. The solution for Squid can be using option item "read_timeout" (i.e. "read_timeout 150 hours"). Not sure about solution for vpnc. If we do not plan to do anything with that on the spice side, we should move the bug to documentation so this is documented, I am just worried about scalability of proxy If we recommend to increase timeout values.
(In reply to Marian Krcmarik from comment #15) > (In reply to Marc-Andre Lureau from comment #13) > > Marian, could you give some update? shouldn't severity be lowered? > Probably It seems to be related to the timeouts for idling connections > (connections with no data transfer) - I can see the problem when using Squid > in default mode - 15mins timetout for connections without data transfer or > even when connection over vpnc 2 hours timeout seems to be default value for > vpnc. IT confused me since I could reproduce it even without Proxy but I > relized It was over vpnc. > > The solution for Squid can be using option item "read_timeout" (i.e. > "read_timeout 150 hours"). Not sure about solution for vpnc. > > If we do not plan to do anything with that on the spice side, we should move > the bug to documentation so this is documented, I am just worried about > scalability of proxy If we recommend to increase timeout values. It will be worse if we try to do anything else (retry connection, more keepalive etc). If people want to keep long idle connection, they need to configure their proxy appropriately. Please move the bug to documentation.
Ok I am moving to Docs. Please write a note about default timeout for idling connection over Squid into section describing Spice proxy setup, Squid in default configuration terminates idling (no data transfer) connection after 15 minutes which consequence is that any idling Spice connection over Squid proxy is terminated in 15 minutes, This may be confusing for users, The timeout can be adjusted by entering option item "read_timeout" into squid,conf, i.e. "read_timeout 10 hours").
Added a note to the end of topic 25669 (in both the Admin and Install guides) stating: "Squid Proxy in the default configuration will terminate its connection after 15 idle minutes. To increase the amount of time before Squid Proxy terminates its idle connection, adjust the read_timeout option in squid.conf (for instance read_timeout 10 hours)." Awaiting rebuild.
Documentation Link ------------------------------ Admin: https://documentation-devel.engineering.redhat.com/site/documentation/en-US/Red_Hat_Enterprise_Virtualization/3.5-Beta/html-single/Administration_Guide/index.html#sect-Squid_Proxy Install: https://documentation-devel.engineering.redhat.com/site/documentation/en-US/Red_Hat_Enterprise_Virtualization/3.5-Beta/html-single/Installation_Guide/index.html#sect-Squid_Proxy What Changed ------------------------------ Installing and Configuring a Squid Proxy [25669-710706] Added a note to the end of the topic stating: "Squid Proxy in the default configuration will terminate its connection after 15 idle minutes. To increase the amount of time before Squid Proxy terminates its idle connection, adjust the read_timeout option in squid.conf (for instance read_timeout 10 hours)." Updated revision history: Admin: [34613-711088] Install: [34615-711077] NVR ------------------------------ Admin: Red_Hat_Enterprise_Virtualization-Administration_Guide-3.5-Beta-web-en-US-3.5-19.el6eng Install: Red_Hat_Enterprise_Virtualization-Installation_Guide-3.5-Beta-web-en-US-3.5-17.el6eng Moving to ON_QA
Reviewed. The new note box appears in both guides. It points users to the read_timeout option in squid.conf. VERIFIED.