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?
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
this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/221