Bug 97227

Summary:	On file transfer, win agent sends STATUS_ERROR after STATUS_SUCCESS
Product:	Spice	Reporter:	Victor Toso <bugzilla>
Component:	win32 agent	Assignee:	Spice Bug List <spice-bugs>
Status:	RESOLVED FIXED	QA Contact:
Severity:	normal
Priority:	medium	CC:	bugzilla
Version:	unspecified
Hardware:	Other
OS:	All
Whiteboard:
i915 platform:		i915 features:

Description Victor Toso 2016-08-06 15:15:13 UTC

Windows VDAgent is sending error for xfer-task id that had xfer-task success already. This never happens with Linux agent and it should not happen on windows VDAgent. From Protocol point of view it does not make any sense.

Example bellow is with a few pending patches upstream being a object reference fix being the most important one so I would suggest using the 'pending' branch at [0] for testing (or wait till it gets pushed)

[0] https://gitlab.com/victortoso/spice-gtk

If it is a regression on spice-gtk for windows guests, it implies different protocol behaviour between linux and windows guest. 7 Files are being copied (one operation) and you can see that after each response 3 (success) we will receive response 2 (error)

This tests uses a win7 guest with spice-guest-tools 0.100

Filing the bug in order to not forget to take a look on it later. Logs below.

[1] spice-gtk log ~ https://paste.fedoraproject.org/402708/49613514/
GSpice-DEBUG: spice-file-transfer-task.c:640 transfer of file chapeu.jpg has started
GSpice-DEBUG: spice-file-transfer-task.c:640 transfer of file confort.jpg has started
GSpice-DEBUG: spice-file-transfer-task.c:640 transfer of file funny-dads-1.jpg has started
GSpice-DEBUG: spice-file-transfer-task.c:640 transfer of file funny-dads-2.jpg has started
GSpice-DEBUG: spice-file-transfer-task.c:640 transfer of file jana.jpg has started
GSpice-DEBUG: spice-file-transfer-task.c:640 transfer of file marvin.jpg has started
GSpice-DEBUG: spice-file-transfer-task.c:640 transfer of file tree.jpg has started
GSpice-DEBUG: channel-main.c:3103 Insert a xfer task:7 to task list
GSpice-DEBUG: channel-main.c:3103 Insert a xfer task:1 to task list
GSpice-DEBUG: channel-main.c:3103 Insert a xfer task:2 to task list
GSpice-DEBUG: channel-main.c:3103 Insert a xfer task:3 to task list
GSpice-DEBUG: channel-main.c:3103 Insert a xfer task:4 to task list
GSpice-DEBUG: channel-main.c:3103 Insert a xfer task:5 to task list
GSpice-DEBUG: channel-main.c:3103 Insert a xfer task:6 to task list
GSpice-DEBUG: channel-main.c:1844 xfer-task 3 received response 0
GSpice-DEBUG: channel-main.c:1844 xfer-task 2 received response 0
GSpice-DEBUG: channel-main.c:1844 xfer-task 1 received response 0
GSpice-DEBUG: channel-main.c:1844 xfer-task 7 received response 0
GSpice-DEBUG: channel-main.c:1844 xfer-task 5 received response 0
GSpice-DEBUG: channel-main.c:1844 xfer-task 4 received response 0
GSpice-DEBUG: channel-main.c:1844 xfer-task 6 received response 0
GSpice-DEBUG: channel-main.c:1844 xfer-task 3 received response 3
GSpice-DEBUG: channel-main.c:1844 xfer-task 1 received response 3
GSpice-DEBUG: channel-main.c:1844 xfer-task 4 received response 3
GSpice-DEBUG: spice-file-transfer-task.c:274 transferred file funny-dads-1.jpg of 43.8 kB size in 0.6 seconds (67.8 kB/s)
GSpice-DEBUG: spice-file-transfer-task.c:274 transferred file chapeu.jpg of 49.9 kB size in 0.7 seconds (75.8 kB/s)
GSpice-DEBUG: spice-file-transfer-task.c:274 transferred file funny-dads-2.jpg of 54.0 kB size in 0.7 seconds (82.1 kB/s)
GSpice-DEBUG: channel-main.c:1844 xfer-task 2 received response 3
GSpice-DEBUG: spice-file-transfer-task.c:274 transferred file confort.jpg of 78.9 kB size in 0.7 seconds (113.6 kB/s)
GSpice-DEBUG: channel-main.c:1844 xfer-task 2 received response 2

GSpice-CRITICAL **: spice_main_channel_find_xfer_task_by_task_id: assertion 'xfer_op != NULL' failed

GSpice-CRITICAL **: main_agent_handle_xfer_status: assertion 'xfer_task != NULL' failed
GSpice-DEBUG: channel-main.c:1844 xfer-task 5 received response 3
GSpice-DEBUG: channel-main.c:1844 xfer-task 7 received response 3
GSpice-DEBUG: spice-file-transfer-task.c:274 transferred file jana.jpg of 155.5 kB size in 0.8 seconds (202.1 kB/s)
GSpice-DEBUG: spice-file-transfer-task.c:274 transferred file tree.jpg of 214.6 kB size in 0.8 seconds (279.0 kB/s)
GSpice-DEBUG: channel-main.c:1844 xfer-task 5 received response 2

GSpice-CRITICAL **: spice_main_channel_find_xfer_task_by_task_id: assertion 'xfer_op != NULL' failed

GSpice-CRITICAL **: main_agent_handle_xfer_status: assertion 'xfer_task != NULL' failed
GSpice-DEBUG: channel-main.c:1844 xfer-task 7 received response 2

GSpice-CRITICAL **: spice_main_channel_find_xfer_task_by_task_id: assertion 'xfer_op != NULL' failed

GSpice-CRITICAL **: main_agent_handle_xfer_status: assertion 'xfer_task != NULL' failed
GSpice-DEBUG: channel-main.c:1844 xfer-task 6 received response 3
GSpice-DEBUG: channel-main.c:2897 Transfer successful (0x275541a0)
Spice-DEBUG: channel-main.c:2903:file_transfer_operation_free: Freeing file-transfer-operation 0x275541a0
GSpice-DEBUG: spice-file-transfer-task.c:274 transferred file marvin.jpg of 307.6 kB size in 1.3 seconds (239.5 kB/s)
GSpice-DEBUG: channel-main.c:1844 xfer-task 6 received response 2

GSpice-CRITICAL **: spice_main_channel_find_xfer_task_by_task_id: assertion 'xfer_op != NULL' failed

GSpice-CRITICAL **: main_agent_handle_xfer_status: assertion 'xfer_task != NULL' failed

[2] VDAgent log
2464::INFO::2016-08-06 17:02:42,078::FileXfer::handle_start::3 funny-dads-1.jpg (43827)
2464::INFO::2016-08-06 17:02:42,125::FileXfer::handle_start::2 confort.jpg (78851)
2464::INFO::2016-08-06 17:02:42,125::FileXfer::handle_start::1 chapeu.jpg (49919)
2464::INFO::2016-08-06 17:02:42,171::FileXfer::handle_start::7 tree.jpg (214629)
2464::INFO::2016-08-06 17:02:42,218::FileXfer::handle_start::5 jana.jpg (155491)
2464::INFO::2016-08-06 17:02:42,218::FileXfer::handle_start::4 funny-dads-2.jpg (54043)
2464::INFO::2016-08-06 17:02:42,218::FileXfer::handle_start::6 marvin.jpg (307621)
2464::INFO::2016-08-06 17:02:42,421::FileXfer::handle_data::3 completed
2464::INFO::2016-08-06 17:02:42,437::FileXfer::handle_data::1 completed
2464::INFO::2016-08-06 17:02:42,437::FileXfer::handle_data::4 completed
2464::INFO::2016-08-06 17:02:42,500::FileXfer::handle_data::2 completed
2464::INFO::2016-08-06 17:02:42,546::FileXfer::handle_data::file id 2 not found
2464::INFO::2016-08-06 17:02:42,578::FileXfer::handle_data::5 completed
2464::INFO::2016-08-06 17:02:42,578::FileXfer::handle_data::7 completed
2464::INFO::2016-08-06 17:02:42,609::FileXfer::handle_data::file id 5 not found
2464::INFO::2016-08-06 17:02:42,609::FileXfer::handle_data::file id 7 not found
2464::INFO::2016-08-06 17:02:43,093::FileXfer::handle_data::6 completed
2464::INFO::2016-08-06 17:02:43,109::FileXfer::handle_data::file id 6 not found

Comment 1 Victor Toso 2016-08-10 14:24:32 UTC

Patch sent https://lists.freedesktop.org/archives/spice-devel/2016-August/031265.html

Comment 2 Victor Toso 2016-11-11 13:28:28 UTC

Correct fix now, sent:
https://lists.freedesktop.org/archives/spice-devel/2016-November/033536.html

Comment 3 Victor Toso 2016-11-14 21:31:01 UTC

https://cgit.freedesktop.org/spice/spice-gtk/commit/?id=885229393e3198bd4b386cf71a51832439dfb31b

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.