Bug 90016

Summary:	IO error on machine shutdown if connected through unix fd socket
Product:	Spice	Reporter:	Zeeshan Ali <zeenix>
Component:	spice-gtk	Assignee:	Spice Bug List <spice-bugs>
Status:	RESOLVED FIXED	QA Contact:
Severity:	normal
Priority:	medium
Version:	unspecified
Hardware:	Other
OS:	All
Whiteboard:
i915 platform:		i915 features:

Description Zeeshan Ali 2015-04-13 15:41:40 UTC

We still get this error from spice on machine shutting down in Boxes if connected through unix fd socket. Filing a new bug and not reopening bug#83692 cause of:

https://bugzilla.gnome.org/show_bug.cgi?id=746806#c1

Here is the spice log:

(gnome-boxes:28499): GSpice-DEBUG: spice-gtk-session.c:176 inputs-3:0: client_modifiers:0x2, guest_modifiers:0x2
(gnome-boxes:28499): GSpice-DEBUG: spice-gtk-session.c:176 inputs-3:0: client_modifiers:0x2, guest_modifiers:0x2
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1476 focus_in_event
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1253 release_keys
(gnome-boxes:28499): GSpice-DEBUG: spice-gtk-session.c:176 inputs-3:0: client_modifiers:0x2, guest_modifiers:0x2
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1446 enter_event
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:727 grab keyboard
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1446 enter_event
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:309 cursor-4:0: set_cursor: flags 0, size 2304
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:316 cursor-4:0: set_cursor: type alpha(0), 0, 24x24
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:309 cursor-4:0: set_cursor: flags 0, size 2304
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:316 cursor-4:0: set_cursor: type alpha(0), 0, 24x24
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1674 button_event press: button 1, state 0x10
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1674 button_event release: button 1, state 0x110
(gnome-boxes:28499): GSpice-DEBUG: channel-main.c:1328 agent connected: no
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1692 display-2:0: 0: FIXME primary destroy, but is display really disabled?
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:435 cursor-4:0: cursor_handle_reset, init_done: 1
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1505 focus_out_event
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1650 primary flags: 1
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:652 display-2:0: Create primary canvas
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2387 cursor_reset: no window, returning
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:435 cursor-4:0: cursor_handle_reset, init_done: 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:267 update monitor area 0:0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2125 update area, primary: 720x400, area: +0+0 1376x778
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1052 recalc geom monitor: 0:0, guest +0+0:720x400, window 1379x778, zoom 1
getting display
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1052 recalc geom monitor: 0:0, guest +0+0:720x400, window 1x1, zoom 1
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1476 focus_in_event
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2702 test cap 1 in 0x12: yes
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1716 display-2:0: monitors config: n: 1/1
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1736 display-2:0: monitor id: 0, surface id: 0, +0+0-720x400
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2391 cursor_reset
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:309 cursor-4:0: set_cursor: flags 1, size 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:267 update monitor area 0:0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2125 update area, primary: 720x400, area: +0+0 720x400
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1052 recalc geom monitor: 0:0, guest +0+0:720x400, window 1x1, zoom 1
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:852 display-2:0: display_handle_mark
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:435 cursor-4:0: cursor_handle_reset, init_done: 1
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2219 widget mark: 1, 0:0 0x17674c0
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1692 display-2:0: 0: FIXME primary destroy, but is display really disabled?
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2391 cursor_reset
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:309 cursor-4:0: set_cursor: flags 1, size 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1505 focus_out_event
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1650 primary flags: 1
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:652 display-2:0: Create primary canvas
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:267 update monitor area 0:0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2125 update area, primary: 640x400, area: +0+0 720x400
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1052 recalc geom monitor: 0:0, guest +0+0:640x400, window 1x1, zoom 1
getting display
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1476 focus_in_event
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2702 test cap 1 in 0x12: yes
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1716 display-2:0: monitors config: n: 1/1
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1736 display-2:0: monitor id: 0, surface id: 0, +0+0-640x400
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:267 update monitor area 0:0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2125 update area, primary: 640x400, area: +0+0 640x400
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1052 recalc geom monitor: 0:0, guest +0+0:640x400, window 1x1, zoom 1
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:852 display-2:0: display_handle_mark
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2219 widget mark: 1, 0:0 0x17674c0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1052 recalc geom monitor: 0:0, guest +0+0:640x400, window 1379x778, zoom 1
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1460 leave_event
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:755 ungrab keyboard
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1446 enter_event
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:727 grab keyboard
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:435 cursor-4:0: cursor_handle_reset, init_done: 1
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1692 display-2:0: 0: FIXME primary destroy, but is display really disabled?
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2391 cursor_reset
(gnome-boxes:28499): GSpice-DEBUG: channel-cursor.c:309 cursor-4:0: set_cursor: flags 1, size 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1505 focus_out_event
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1650 primary flags: 1
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:652 display-2:0: Create primary canvas
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:267 update monitor area 0:0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2125 update area, primary: 720x400, area: +0+0 640x400
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1052 recalc geom monitor: 0:0, guest +0+0:640x400, window 1379x778, zoom 1
getting display
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1052 recalc geom monitor: 0:0, guest +0+0:640x400, window 1x1, zoom 1
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1476 focus_in_event
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2702 test cap 1 in 0x12: yes
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1716 display-2:0: monitors config: n: 1/1
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:1736 display-2:0: monitor id: 0, surface id: 0, +0+0-720x400
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:267 update monitor area 0:0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2125 update area, primary: 720x400, area: +0+0 720x400
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1052 recalc geom monitor: 0:0, guest +0+0:720x400, window 1x1, zoom 1
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:852 display-2:0: display_handle_mark
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2219 widget mark: 1, 0:0 0x17674c0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1052 recalc geom monitor: 0:0, guest +0+0:720x400, window 1379x778, zoom 1
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1460 leave_event
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:755 ungrab keyboard
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1446 enter_event
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:727 grab keyboard
(gnome-boxes:28499): GSpice-DEBUG: spice-gtk-session.c:176 inputs-3:0: client_modifiers:0x2, guest_modifiers:0x0
(gnome-boxes:28499): GSpice-DEBUG: spice-gtk-session.c:176 inputs-3:0: client_modifiers:0x2, guest_modifiers:0x0
(gnome-boxes:28499): GSpice-DEBUG: spice-gtk-session.c:176 inputs-3:0: client_modifiers:0x2, guest_modifiers:0x0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1460 leave_event
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:755 ungrab keyboard
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1460 leave_event
(gnome-boxes:28499): GSpice-DEBUG: spice-gtk-session.c:176 inputs-3:0: client_modifiers:0x2, guest_modifiers:0x0
(gnome-boxes:28499): GSpice-DEBUG: spice-gtk-session.c:176 inputs-3:0: client_modifiers:0x2, guest_modifiers:0x0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:922 main-1:0: Closing the connection: spice_channel_read() - ret=0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2152 main-1:0: channel got error
Boxes-Message: machine.vala:164: display Red Hat Enterprise Linux 6.6 disconnected
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1505 focus_out_event
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:1253 release_keys
getting display
(gnome-boxes:28499): GSpice-DEBUG: spice-session.c:1774 session: disconnecting 0
Cleared displays
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2421 main-1:0: Coroutine exit main-1:0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:922 cursor-4:0: Closing the connection: spice_channel_read() - ret=0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2152 cursor-4:0: channel got error
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:922 inputs-3:0: Closing the connection: spice_channel_read() - ret=0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2152 inputs-3:0: channel got error
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:922 display-2:0: Closing the connection: spice_channel_read() - ret=0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2152 display-2:0: channel got error
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2475 channel_destroy 0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2664 inputs-3:0: channel disconnect 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2475 channel_destroy 0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2664 display-2:0: channel disconnect 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2475 channel_destroy 0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2664 cursor-4:0: channel disconnect 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2475 channel_destroy 0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2664 record-6:0: channel disconnect 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2475 channel_destroy 0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2664 playback-5:0: channel disconnect 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2475 channel_destroy 0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2664 usbredir-9:0: channel disconnect 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2475 channel_destroy 1
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2664 usbredir-9:1: channel disconnect 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2475 channel_destroy 2
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2664 usbredir-9:2: channel disconnect 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2475 channel_destroy 3
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2664 usbredir-9:3: channel disconnect 0
(gnome-boxes:28499): GSpice-DEBUG: spice-widget.c:2475 channel_destroy 0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2664 main-1:0: channel disconnect 0
(gnome-boxes:28499): GSpice-DEBUG: spice-session.c:1579 no migration in progress
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2620 main-1:0: reset 
(gnome-boxes:28499): GSpice-DEBUG: channel-main.c:1328 agent connected: no
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2421 cursor-4:0: Coroutine exit cursor-4:0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2421 inputs-3:0: Coroutine exit inputs-3:0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2421 display-2:0: Coroutine exit display-2:0
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2553 main-1:0: channel reset
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2620 cursor-4:0: reset 
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2553 cursor-4:0: channel reset
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2620 inputs-3:0: reset 
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2553 inputs-3:0: channel reset
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2620 display-2:0: reset 
(gnome-boxes:28499): GSpice-DEBUG: channel-display.c:767 display-2:0: keeping exisiting primary surface, migration or reset
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2553 display-2:0: channel reset
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2173 main-1:0: Delayed unref channel 0x1f5e920
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2173 cursor-4:0: Delayed unref channel 0x1f72c00
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2173 inputs-3:0: Delayed unref channel 0x17cf070
(gnome-boxes:28499): GSpice-DEBUG: spice-channel.c:2173 display-2:0: Delayed unref channel 0x1f73f70

Comment 1 Marc-Andre Lureau 2015-04-13 17:10:36 UTC

Not spice-gtk fault,

On regular direct spice server socket, we get clean shutdown with poll G_IO_IN and read=0.

with a libvirt provided fd, it gets  G_IO_IN | G_IO_HUP.

Further investigation required on libvirt side.

Comment 2 Marc-Andre Lureau 2015-04-13 17:14:50 UTC

libvirt used a socketpair, and passes them to qemu/spice using spice_server_add_client

Comment 3 Marc-Andre Lureau 2015-04-13 17:24:41 UTC

it looks like spice server could use more shutdown() calls here and there.

Comment 4 Zeeshan Ali 2015-04-13 17:57:41 UTC

(In reply to Marc-Andre Lureau from comment #3)
> it looks like spice server could use more shutdown() calls here and there.

Is that a side-comment or would that help with this bug?

Comment 5 Marc-Andre Lureau 2015-04-14 10:32:10 UTC

After further research, I think it's expected to get HUP, it doesn't get it with tcp sockets, only local sockets (that's annoying..)  It happens on regular close() conditions, so I would just ignore it for now.

A clean shutdown would involve a new message to tell the client to first close its end, in order to avoid the HUP. That way the client could distinguish normal termination from unexpected ones.

http://lists.freedesktop.org/archives/spice-devel/2015-April/019461.html

Comment 6 Christophe Fergeau 2015-09-07 15:21:19 UTC

Was pushed as http://cgit.freedesktop.org/spice/spice-gtk/commit/?id=372716d93ed929

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.