Bug#941863: XDamage events are intermingled with GetImage response
On 2019-10-06 9:37 p.m., Petr Vandrovec wrote:
Package: xserver-xorg-core
Version: 2:1.20.4-1
For over a year vino-server is crashing on me on startup, complaining
that unknown sequence was received from X server:
[xcb] Unknown sequence number while processing queue
[xcb] Most likely this is a multi-threaded client and XInitThreads has not been
called
[xcb] Aborting, sorry about that.
vino-server: ../../src/xcb_io.c:260: poll_for_event: Assertion
`!xcb_xlib_threads_sequence_lost' failed.
Aborted (core dumped)
vino-server does not use X session from multiple threads, and no amount of
added locking solved the problem. Only thing that worked was running
vino-server under strace - if strace is attached, there is no crash.
So I added logging everywhere, to find that just before bogus sequence
is detected, client makes GetImage call - and data returned for that call
are corrupted (assert for len != 1976 is added to stop process in its tracks
when GetImage with corrupted response arrives):
(gdb) bt
#0 0x7fb954978081 in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:50
#1 0x7fb954963535 in __GI_abort () at abort.c:79
#2 0x7fb95496340f in __assert_fail_base
(fmt=0x7fb954ac5710 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x7fb953bf1260 "len
!= 1976", file=0x7fb953bf121c "../../src/xcb_in.c", line=413, function=)
at assert.c:92
#3 0x7fb954970b92 in __GI___assert_fail
(assertion=assertion@entry=0x7fb953bf1260 "len != 1976", file=file@entry=0x7fb953bf121c
"../../src/xcb_in.c", line=line@entry=413, function=function@entry=0x7fb953bf12d0
<__PRETTY_FUNCTION__.11208
"read_block") at assert.c:101
#4 0x7fb953be0ddc in read_block (len=, buf=0x557810253fd0,
fd=3) at ../../src/xcb_in.c:413
#5 0x7fb953be0ddc in _xcb_in_read_block (c=c@entry=0x55780ffe0e60,
buf=buf@entry=0x557810253fb0, len=len@entry=2008) at ../../src/xcb_in.c:1087
#6 0x7fb953be110f in read_packet (c=0x55780ffe0e60) at
../../src/xcb_in.c:268
#7 0x7fb953be110f in _xcb_in_read (c=c@entry=0x55780ffe0e60) at
../../src/xcb_in.c:1042
#8 0x7fb953bdef7f in _xcb_conn_wait (c=c@entry=0x55780ffe0e60,
cond=cond@entry=0x7fffe9524360, vector=vector@entry=0x0, count=count@entry=0x0)
at ../../src/xcb_conn.c:515
#9 0x7fb953be061f in wait_for_reply (c=c@entry=0x55780ffe0e60,
request=request@entry=467, e=e@entry=0x7fffe9524420) at ../../src/xcb_in.c:525
#10 0x7fb953be0792 in xcb_wait_for_reply64 (c=c@entry=0x55780ffe0e60,
request=467, e=e@entry=0x7fffe9524420) at ../../src/xcb_in.c:569
#11 0x7fb955183e38 in _XReply (dpy=dpy@entry=0x55780ffdfba0,
rep=rep@entry=0x7fffe9524480, extra=extra@entry=0, discard=discard@entry=0) at
../../src/xcb_io.c:609
#12 0x7fb9551691dc in XGetImage (dpy=0x55780ffdfba0, d=1001, x=1465,
y=1162, width=26, height=38, plane_mask=18446744073709551615, format=2) at
../../src/GetImage.c:76
#13 0x7fb95516946a in XGetSubImage
(dpy=, d=, x=x@entry=1465, y=y@entry=1162,
width=width@entry=26, height=height@entry=38, plane_mask=18446744073709551615, format=2,
dest_image=0x5578101502e0, dest_x=
1465, dest_y=1162) at ../../src/GetImage.c:138
#14 0x55780fe076fa in vino_fb_xdamage_idle_handler (vfb=0x55781017cd00
[VinoFB]) at server/vino-fb.c:602
#15 0x7fb955881d8e in g_main_dispatch (context=0x55781000fc40) at
../../../glib/gmain.c:3179
#16 0x7fb955881d8e in g_main_context_dispatch
(context=context@entry=0x55781000fc40) at ../../../glib/gmain.c:3844
#17 0x7fb955882140 in g_main_context_iterate (context=0x55781000fc40,
block=block@entry=1, dispatch=dispatch@entry=1, self=) at
../../../glib/gmain.c:3917
#18 0x7fb955882413 in g_main_loop_run (loop=0x557810056210) at
../../../glib/gmain.c:4111
#19 0x55780fe06f7d in main (argc=, argv=) at
server/vino-main.c:319
Received response header says that image with 494 dwords should be received:
(gdb) frame 5
#5 _xcb_in_read_block (c=c@entry=0x55780ffe0e60, buf=buf@entry=0x557810253fb0,
len=len@entry=2008) at ../../src/xcb_in.c:1087
1087int ret = read_block(c->fd, (char *) buf + done, len - done);
(gdb) print *(xcb_generic_event_t*) buf
$1 = {response_type = 1 '\001', pad0 = 16 '\020', sequence = 467, pad = {494,
33, 0, 0, 0, 0, 0}, full_sequence = 30605658}
But image data do not look anything like image data. Instead they look like
XDamage event
(xdpyinfo confirms that 90 is XDAMAGE event):
(gdb) frame 4
#4 0x7fb953be0ddc in read_block (len=, buf=0x557810253fd0,
fd=3) at ../../src/xcb_in.c:413
413 assert(len != 1976);
(gdb) x /10bx buf
0x557810253fd0: 0x5a0x010xd30x010xe90x030x000x00
0x557810253fd8: 0x060x00
(gdb) print *(xcb_generic_event_t*) buf
$2 = {response_type = 90 'Z', pad0 = 1 '\001', sequence = 467, pad = {1001,
37748742, 1583889968, 76678587, 1441814, 0, 78644800}, full_sequence =
4156487614}
So somehow XDamage event got inserted between GetImage response header, and
image
Bug#941863: XDamage events are intermingled with GetImage response
Package: xserver-xorg-core
Version: 2:1.20.4-1
For over a year vino-server is crashing on me on startup, complaining
that unknown sequence was received from X server:
[xcb] Unknown sequence number while processing queue
[xcb] Most likely this is a multi-threaded client and XInitThreads has not been
called
[xcb] Aborting, sorry about that.
vino-server: ../../src/xcb_io.c:260: poll_for_event: Assertion
`!xcb_xlib_threads_sequence_lost' failed.
Aborted (core dumped)
vino-server does not use X session from multiple threads, and no amount of
added locking solved the problem. Only thing that worked was running
vino-server under strace - if strace is attached, there is no crash.
So I added logging everywhere, to find that just before bogus sequence
is detected, client makes GetImage call - and data returned for that call
are corrupted (assert for len != 1976 is added to stop process in its tracks
when GetImage with corrupted response arrives):
(gdb) bt
#0 0x7fb954978081 in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:50
#1 0x7fb954963535 in __GI_abort () at abort.c:79
#2 0x7fb95496340f in __assert_fail_base
(fmt=0x7fb954ac5710 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
assertion=0x7fb953bf1260 "len != 1976", file=0x7fb953bf121c
"../../src/xcb_in.c", line=413, function=)
at assert.c:92
#3 0x7fb954970b92 in __GI___assert_fail
(assertion=assertion@entry=0x7fb953bf1260 "len != 1976",
file=file@entry=0x7fb953bf121c "../../src/xcb_in.c", line=line@entry=413,
function=function@entry=0x7fb953bf12d0 <__PRETTY_FUNCTION__.11208
> "read_block") at assert.c:101
#4 0x7fb953be0ddc in read_block (len=, buf=0x557810253fd0,
fd=3) at ../../src/xcb_in.c:413
#5 0x7fb953be0ddc in _xcb_in_read_block (c=c@entry=0x55780ffe0e60,
buf=buf@entry=0x557810253fb0, len=len@entry=2008) at ../../src/xcb_in.c:1087
#6 0x7fb953be110f in read_packet (c=0x55780ffe0e60) at
../../src/xcb_in.c:268
#7 0x7fb953be110f in _xcb_in_read (c=c@entry=0x55780ffe0e60) at
../../src/xcb_in.c:1042
#8 0x7fb953bdef7f in _xcb_conn_wait (c=c@entry=0x55780ffe0e60,
cond=cond@entry=0x7fffe9524360, vector=vector@entry=0x0, count=count@entry=0x0)
at ../../src/xcb_conn.c:515
#9 0x7fb953be061f in wait_for_reply (c=c@entry=0x55780ffe0e60,
request=request@entry=467, e=e@entry=0x7fffe9524420) at ../../src/xcb_in.c:525
#10 0x7fb953be0792 in xcb_wait_for_reply64 (c=c@entry=0x55780ffe0e60,
request=467, e=e@entry=0x7fffe9524420) at ../../src/xcb_in.c:569
#11 0x7fb955183e38 in _XReply (dpy=dpy@entry=0x55780ffdfba0,
rep=rep@entry=0x7fffe9524480, extra=extra@entry=0, discard=discard@entry=0) at
../../src/xcb_io.c:609
#12 0x7fb9551691dc in XGetImage (dpy=0x55780ffdfba0, d=1001, x=1465,
y=1162, width=26, height=38, plane_mask=18446744073709551615, format=2) at
../../src/GetImage.c:76
#13 0x7fb95516946a in XGetSubImage
(dpy=, d=, x=x@entry=1465, y=y@entry=1162,
width=width@entry=26, height=height@entry=38, plane_mask=18446744073709551615,
format=2, dest_image=0x5578101502e0, dest_x=
1465, dest_y=1162) at ../../src/GetImage.c:138
#14 0x55780fe076fa in vino_fb_xdamage_idle_handler (vfb=0x55781017cd00
[VinoFB]) at server/vino-fb.c:602
#15 0x7fb955881d8e in g_main_dispatch (context=0x55781000fc40) at
../../../glib/gmain.c:3179
#16 0x7fb955881d8e in g_main_context_dispatch
(context=context@entry=0x55781000fc40) at ../../../glib/gmain.c:3844
#17 0x7fb955882140 in g_main_context_iterate (context=0x55781000fc40,
block=block@entry=1, dispatch=dispatch@entry=1, self=) at
../../../glib/gmain.c:3917
#18 0x7fb955882413 in g_main_loop_run (loop=0x557810056210) at
../../../glib/gmain.c:4111
#19 0x55780fe06f7d in main (argc=, argv=) at
server/vino-main.c:319
Received response header says that image with 494 dwords should be received:
(gdb) frame 5
#5 _xcb_in_read_block (c=c@entry=0x55780ffe0e60, buf=buf@entry=0x557810253fb0,
len=len@entry=2008) at ../../src/xcb_in.c:1087
1087int ret = read_block(c->fd, (char *) buf + done, len - done);
(gdb) print *(xcb_generic_event_t*) buf
$1 = {response_type = 1 '\001', pad0 = 16 '\020', sequence = 467, pad = {494,
33, 0, 0, 0, 0, 0}, full_sequence = 30605658}
But image data do not look anything like image data. Instead they look like
XDamage event
(xdpyinfo confirms that 90 is XDAMAGE event):
(gdb) frame 4
#4 0x7fb953be0ddc in read_block (len=, buf=0x557810253fd0,
fd=3) at ../../src/xcb_in.c:413
413 assert(len != 1976);
(gdb) x /10bx buf
0x557810253fd0: 0x5a0x010xd30x010xe90x030x000x00
0x557810253fd8: 0x060x00
(gdb) print *(xcb_generic_event_t*) buf
$2 = {response_type = 90 'Z', pad0 = 1 '\001', sequence = 467, pad = {1001,
37748742, 1583889968, 76678587, 1441814, 0, 78644800}, full_sequence =
4156487614}
So somehow XDamage event got inserted between GetImage response header, and
image data. Note that drawable
returned by XDamage (1001)
