Xpra: Ticket #221: Still places that queue from the draw_thread_loop instead of the main thread

I get these sometimes:

2012-12-06 15:56:29,327 error processing draw packet
Traceback (most recent call last):
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/client.py", line 960, in _draw_thread_loop
    self._do_draw(packet)
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/client.py", line 981, in _do_draw
    self.send_damage_sequence(wid, packet_sequence, width, height, -1)
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/client.py", line 954, in send_damage_sequence
    self.send_now("damage-sequence", packet_sequence, wid, width, height, decode_time)
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/client_base.py", line 177, in send_now
    self._protocol.source.queue_priority_packet(parts)
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/client_base.py", line 46, in queue_priority_packet
    self._protocol.source_has_more()
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/protocol.py", line 175, in source_has_more
    self._flush_one_packet_into_buffer()
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/protocol.py", line 210, in _flush_one_packet_into_buffer
    assert self._main_thread==threading.currentThread(), "queuing should only be called from the main thread!"
AssertionError: queuing should only be called from the main thread!

The problem was quite reproducible before I patched my Xpra as described in ticket #220, so I think it might actually not be the problem of the draw_thread_loop to begin with.

Unfortunately, I still get it after that fix, but the only way I can trigger it reliably is to use PasswordMaker? (http://passwordmaker.org/) in Firefox to populate a password. It does *not* happen when I simply open or close the PasswordMaker? dialogue, but only when I ask it to populate a password field. I also managed to get the error only for certain passwords (i.e. the problem occurs when I use 1234, but not for 123, 12 or 1).

All the while, the server log does not show anything else.

With '-d all' I get this log:

2012-12-06 16:13:27,749 process_draw 1 bytes for window 111 using mmap encoding with options={}
2012-12-06 16:13:27,749 draw_region(775, 316, 93, 30, mmap, 1 bytes, 280, {}, [<function record_decode_time at 0x267cc80>, <function after_draw_refresh at 0x267cb90>])
2012-12-06 16:13:27,749 record_decode_time(True) wid=111, mmap: 93x30, 0.4ms
2012-12-06 16:13:27,750 after_draw_refresh(True) options={}
2012-12-06 16:13:27,750 do_expose_event(<gtk.gdk.Event at 0x243a968: GDK_EXPOSE area=[775, 316, 93, 30]>) area=gtk.gdk.Rectangle(775, 316, 93, 30)
2012-12-06 16:13:27,767 process_draw 1 bytes for window 111 using mmap encoding with options={}
2012-12-06 16:13:27,767 draw_region(673, 316, 93, 30, mmap, 1 bytes, 280, {}, [<function record_decode_time at 0x267cc80>, <function after_draw_refresh at 0x267cb90>])
2012-12-06 16:13:27,768 record_decode_time(True) wid=111, mmap: 93x30, 0.3ms
2012-12-06 16:13:27,768 after_draw_refresh(True) options={}
2012-12-06 16:13:27,768 process_draw 1 bytes for window 111 using mmap encoding with options={}
2012-12-06 16:13:27,768 draw_region(775, 316, 93, 30, mmap, 1 bytes, 280, {}, [<function record_decode_time at 0x267ced8>, <function after_draw_refresh at 0x267ccf8>])
2012-12-06 16:13:27,769 do_expose_event(<gtk.gdk.Event at 0x243a968: GDK_EXPOSE area=[673, 316, 93, 30]>) area=gtk.gdk.Rectangle(673, 316, 93, 30)
2012-12-06 16:13:27,769 record_decode_time(True) wid=111, mmap: 93x30, 0.5ms
2012-12-06 16:13:27,769 after_draw_refresh(True) options={}
2012-12-06 16:13:27,770 do_expose_event(<gtk.gdk.Event at 0x243a968: GDK_EXPOSE area=[775, 316, 93, 30]>) area=gtk.gdk.Rectangle(775, 316, 93, 30)
2012-12-06 16:13:27,803 process_draw 1 bytes for window 111 using mmap encoding with options={}
2012-12-06 16:13:27,803 draw_region(673, 316, 93, 30, mmap, 1 bytes, 280, {}, [<function record_decode_time at 0x267ced8>, <function after_draw_refresh at 0x267ccf8>])
2012-12-06 16:13:27,803 record_decode_time(True) wid=111, mmap: 93x30, 0.2ms
2012-12-06 16:13:27,804 after_draw_refresh(True) options={}
2012-12-06 16:13:27,804 do_expose_event(<gtk.gdk.Event at 0x243a968: GDK_EXPOSE area=[673, 316, 93, 30]>) area=gtk.gdk.Rectangle(673, 316, 93, 30)
2012-12-06 16:13:28,588 process_draw 1 bytes for window 111 using mmap encoding with options={}
2012-12-06 16:13:28,588 draw_region(775, 316, 93, 30, mmap, 1 bytes, 280, {}, [<function record_decode_time at 0x267ced8>, <function after_draw_refresh at 0x267ccf8>])
2012-12-06 16:13:28,588 record_decode_time(True) wid=111, mmap: 93x30, 0.2ms
2012-12-06 16:13:28,589 after_draw_refresh(True) options={}
2012-12-06 16:13:28,589 do_expose_event(<gtk.gdk.Event at 0x243a968: GDK_EXPOSE area=[775, 316, 93, 30]>) area=gtk.gdk.Rectangle(775, 316, 93, 30)
2012-12-06 16:13:29,278 _focus_change((<ClientWindow object at 0x2716230 (xpra+client_window+ClientWindow at 0x2782c60)>, <GParamBoolean 'has-toplevel-focus'>))
2012-12-06 16:13:29,278 update_focus(111,True) _focused=None
2012-12-06 16:13:29,295 process_draw 1 bytes for window 111 using mmap encoding with options={}
2012-12-06 16:13:29,295 draw_region(0, 0, 883, 357, mmap, 1 bytes, 2652, {}, [<function record_decode_time at 0x267ccf8>, <function after_draw_refresh at 0x267ced8>])
2012-12-06 16:13:29,295 process_draw 1 bytes for window 111 using mmap encoding with options={}
2012-12-06 16:13:29,297 record_decode_time(True) wid=111, mmap: 883x357, 1.8ms
2012-12-06 16:13:29,297 draw_region(0, 0, 883, 357, mmap, 1 bytes, 2652, {}, [<function record_decode_time at 0x267cc80>, <function after_draw_refresh at 0x267cb90>])
2012-12-06 16:13:29,299 after_draw_refresh(True) options={}
2012-12-06 16:13:29,299 do_expose_event(<gtk.gdk.Event at 0x243a968: GDK_EXPOSE area=[0, 0, 883, 357]>) area=gtk.gdk.Rectangle(0, 0, 883, 357)
2012-12-06 16:13:29,305 record_decode_time(True) wid=111, mmap: 883x357, 7.8ms
2012-12-06 16:13:29,306 after_draw_refresh(True) options={}
2012-12-06 16:13:29,306 do_expose_event(<gtk.gdk.Event at 0x243a968: GDK_EXPOSE area=[0, 0, 883, 357]>) area=gtk.gdk.Rectangle(0, 0, 883, 357)
2012-12-06 16:13:29,450 update_focus(111,False) _focused=111
2012-12-06 16:13:29,452 <class 'xpra.window_backing.PixmapBacking'>.close() video_decoder=None
2012-12-06 16:13:29,454 _focus_change((<ClientWindow object at 0x271c960 (xpra+client_window+ClientWindow at 0x2782120)>, <GParamBoolean 'has-toplevel-focus'>))
2012-12-06 16:13:29,454 update_focus(2,True) _focused=None
2012-12-06 16:13:29,455 setting new cursor: xterm=<enum GDK_XTERM of type GdkCursorType>
2012-12-06 16:13:29,457 do_expose_event(<gtk.gdk.Event at 0x243a968: GDK_EXPOSE area=[0, 0, 883, 330]>) area=gtk.gdk.Rectangle(0, 0, 883, 330)
2012-12-06 16:13:29,459 setting new cursor: left_ptr=<enum GDK_LEFT_PTR of type GdkCursorType>
2012-12-06 16:13:29,465 error processing draw packet
Traceback (most recent call last):
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/client.py", line 960, in _draw_thread_loop
    self._do_draw(packet)
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/client.py", line 981, in _do_draw
    self.send_damage_sequence(wid, packet_sequence, width, height, -1)
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/client.py", line 954, in send_damage_sequence
    self.send_now("damage-sequence", packet_sequence, wid, width, height, decode_time)
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/client_base.py", line 177, in send_now
    self._protocol.source.queue_priority_packet(parts)
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/client_base.py", line 46, in queue_priority_packet
    self._protocol.source_has_more()
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/protocol.py", line 175, in source_has_more
    self._flush_one_packet_into_buffer()
  File "/home/gene099/fiji/modules/Xpra/src/install/lib/python/xpra/protocol.py", line 210, in _flush_one_packet_into_buffer
    assert self._main_thread==threading.currentThread(), "queuing should only be called from the main thread!"
AssertionError: queuing should only be called from the main thread!

FWIW this is all done using a couple of patches on top of r2180, but only touching src/{setup.py,xpra.README,xpra/server.py} (where the patch to server.py is the one attached to ticket #220).

Any idea how I can debug this more?



Fri, 07 Dec 2012 02:25:18 GMT - Antoine Martin: status, description changed; resolution set

Fixed in r2196 Sorry, was meant to commit this yesterday.. (will need to backport to 0.7.x too)

FYI: this is reproducible simply by closing a window which is getting a lot of redraws, the client will often be able to destroy the window before the last draw event is received


Sat, 23 Jan 2021 04:48:48 GMT - migration script:

this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/221