Arroyo.cc / debug / Debug log: segfaults in drawterm on Wayland

For a long time now, I have stopped using plan 9 from user space. I got tired of the compromises plan9port makes to fit into the limitations of Unix systems. Instead, I run 9front VMs and connect to them over the network. Thanks to drawterm, this is a very seamless experience; copy/paste works, I can access files on the machine running drawterm easily under /mnt/term, including the devices for local networking, for audio, and some of the rendering is performed or cached locally, which makes it feel pretty snappy.

Drawterm is a portable program, and can be built for many different graphics systems, including X11, Windows, and Wayland. With the wayland backend, I would occasionally find that drawterm would crash, maybe about once a week. This was on my desktop, which I keep always on, just turning the monitor off when I'm not using it. Usually, the crash would happen when I turned on my monitor. I could see in the output of dmesg a line such as:

drawterm[4620]: segfault at 7fe876abe828 ip 00007fe88fee6b09 sp 00007fe848ff0588 error 4 in libc.so.6[15ab09,7fe88fdb4000+15b000] likely on CPU 7 (core 7, socket 0)

I have core dumps enabled, and so the crash generates a core file in the current working directory of drawterm. I can get a stack trace like so:

$ gdb ~/src/git.9front.org/plan9front/drawterm/drawterm ~/core
(gdb) bt
#0  0x00007fe88fee6b09 in __memmove_avx_unaligned_erms () from /gnu/store/m31vlvwm79m89fk3xk0z4h7snk61y510-glibc-2.41/lib/libc.so.6
#1  0x0000000000463d9d in wlflush (wl=0x2eff2d40) at wl-screen.c:58
#2  0x0000000000464074 in flushmemscreen (r=...) at wl-screen.c:159
#3  0x00000000004233e2 in drawflush () at devdraw.c:425
#4  drawmesg (client=client@entry=0x7fe860005880, av=av@entry=0x2f10497f, n=1, n@entry=721) at devdraw.c:2071
#5  0x0000000000423852 in drawwrite (c=0x2f000b60, a=0x2f10497f, n=721, off=<optimized out>) at devdraw.c:1324
#6  0x00000000004130ef in kwrite (fd=fd@entry=17, buf=buf@entry=0x2f10497f, len=len@entry=721, offp=offp@entry=0x7fe848ff0968) at sysfile.c:769
#7  0x00000000004151ba in _syspwrite (fd=17, buf=0x2f10497f, len=721, off=<optimized out>) at sysfile.c:796
#8  syspwrite (fd=17, buf=0x2f10497f, n=721, off=105585572) at sysfile.c:1374
#9  0x00000000004321fa in slavewrite (p=p@entry=0x2f104720) at exportsrv.c:624
#10 0x0000000000432350 in blockingslave (arg=0x7fe8640485a0) at exportsrv.c:490
#11 0x0000000000417cd3 in tramp (vp=0x2f0e36a0) at posix.c:119
#12 0x00007fe88fe1caed in start_thread () from /gnu/store/m31vlvwm79m89fk3xk0z4h7snk61y510-glibc-2.41/lib/libc.so.6
#13 0x00007fe88fe97768 in __clone3 () from /gnu/store/m31vlvwm79m89fk3xk0z4h7snk61y510-glibc-2.41/lib/libc.so.6

Where the offending part of wlflush looks like this:

for(p.y = wl->r.min.y; p.y < wl->r.max.y; p.y++)
→	memcpy(wl->shm_data+(p.y*wl->dx+p.x)*4, byteaddr(gscreen, p), Dx(wl->r)*4);

The first few times this happened, I did not read the segfault properly. I thought that, because the crash tended to happen when I turned the screen on, that perhaps the wayland compositor had invalidated the shared memory buffer addressed by wl->shm_data. I set out to reproduce the issue with the WAYLAND_DEBUG=1 variable set, which produced a deluge of logs. The sheer volume logs, and the infrequency of the crash, put me off and lead me to tolerate the issue for quite some time.

After a break, however, I came back to this issue with fresh eyes, and I took my time to debug this with fewer assumptions. Starting out with the kernel's warning about the segfault:

drawterm[4620]: segfault at 7fe876abe828 ip 00007fe88fee6b09 sp 00007fe848ff0588 error 4 in libc.so.6[15ab09,7fe88fdb4000+15b000] likely on CPU 7 (core 7, socket 0)

I know that drawterm attempted to access address 0x7fe876abe828. Going back to gdb, I can try to determine where that address came from. I can print the last instruction before the segfault:

(gdb) frame 0
#0  0x00007fe88fee6b09 in __memmove_avx_unaligned_erms () from /gnu/store/m31vlvwm79m89fk3xk0z4h7snk61y510-glibc-2.41/lib/libc.so.6
(gdb) x/i $pc
=> 0x7fe88fee6b09 <__memmove_avx_unaligned_erms+9>:	vmovdqu (%rsi),%ymm0

So we are trying to load the value at the memory address stored in the %rsi register into the 256-bit %ymm0 register. If we check the System V calling convention, we can see that %rsi holds the second parameter to a function. So unless it was overwritten in the body of the memmove implementation, it would be the second argument here:

memcpy(wl->shm_data+(p.y*wl->dx+p.x)*4, byteaddr(gscreen, p), Dx(wl->r)*4);

Here is byteaddr:

uchar*
byteaddr(Memimage *i, Point p)
{
	uchar *a = i->data->bdata+i->zero;
	return a + p.y*(int)(sizeof(ulong)*i->width) + ((p.x*i->depth) >> 3);
}

We can try recomputing this expression to see if it produces the same memory address:

(gdb) print (gscreen->data->bdata + gscreen->zero) + (p.y * (sizeof(int) * gscreen->width)) + ((wl->r.min.x * gscreen->depth) >> 3)
❌️ value has been optimized out
(gdb) print p
$6 = {x = <optimized out>, y = 1409}

It looks like gcc performed some inlining and was able to eliminate the space used by p.x. If we look at more context in wlflush:

	if(wl->dirty){
		p.x = wl->r.min.x;
		for(p.y = wl->r.min.y; p.y < wl->r.max.y; p.y++)
			memcpy(wl->shm_data+(p.y*wl->dx+p.x)*4, byteaddr(gscreen, p), Dx(wl->r)*4);
		wl_surface_damage(wl->surface, p.x, wl->r.min.y, Dx(wl->r), Dy(wl->r));
		wl->dirty = 0;
	}

then it should be clearer; the compiler decided it could substitute wl->r.min.x for p.x. So we can try the same thing:

(gdb) print/x (gscreen->data->bdata + gscreen->zero) + (p.y * (sizeof(int) * gscreen->width)) + ((wl->r.min.x * gscreen->depth) >> 3)
$7 = 0x7fe876abe828
(gdb) print/x $rsi
$8 = 0x7fe876abe828

All right! So now we know that byteaddr(gscreen, p) is an invalid address. We know p is a position (specifically, the start of a row) in the rectangle wl->r. The global variable gscreen is a structure containing the pixel data for the screen, It is copied into the shared memory buffer wl->shm_data whenever the visible screen needs to be updated. From reading wlflush, we can surmise that it is stored in row-major order, as the code iterates over the height of wl->r, the viewing rectangle for the window in Wayland. It has to do this row-by-row because Wayland allows for the shared memory buffer to have gaps between rows, I assume to be able to align the data better. Comparing the value of p and wl->r:

$11 = {x = <optimized out>, y = 1409}
(gdb) print wl->r
$12 = {min = {x = 2047, y = 1235}, max = {x = 2287, y = 1432}}
(gdb)

We can see that y is not equal to wl->min.y, the initial value for p.y. So some iterations of the loop in wlflush were successful; gscreen must have some space, but not enough to fill the entire window. So we want to look for parts of the code that modify gscreen without modifying wl->r to match it. If we ignore wlattach, which only runs when drawterm is started, there is only wlresize:

void
wlresize(Wlwin *wl, int x, int y)
{
	Rectangle r;

	wl->dx = x;
	wl->dy = y;

	qlock(&drawlock);
	wlallocbuffer(wl);
	r = Rect(0, 0, wl->dx, wl->dy);
	if(gscreen != nil)
		freememimage(gscreen);
	gscreen = allocmemimage(r, XRGB32);
	gscreen->clipr = ZR;
	qunlock(&drawlock);

	screenresize(r);

	qlock(&drawlock);
	wl->dirty = 1;
	wl->r = r;
	wlflush(wl);
	qunlock(&drawlock);
}

perhaps you can see a problem already. Between the time when gscreen is modified to fit r, and the time when wl->r is updated to match, the code releases drawlock, calls screenresize, then takes drawlock again.

T1:	gscreen = allocmemimage(r, XRGB32);
	gscreen->clipr = ZR;
T2:	qunlock(&drawlock);

	screenresize(r);

T3:	qlock(&drawlock);
	wl->dirty = 1;
T4:	wl->r = r;

If drawlock is being used to exclude other threads which might call wlflush, and one of those threads succeeds in taking drawlock between T2 and T3, we would observe the exact conditions seen in this crash; the pixels covered by the viewing rectangle wl->r can be different from the pixels stored in gscreen. What does screenresize do?

void
screenresize(Rectangle r)
{
	qlock(&drawlock);
	resize.r = r;
	resize.f = 1;
	wakeup(&resize.z);
	qunlock(&drawlock);
}

It simply wakes up a condition variable; perhaps some other thread is waiting on it. Usefully, it stores its argument in the global variable resize. Let's compare it to wl->r:

(gdb) print wl->r
$13 = {min = {x = 2047, y = 1235}, max = {x = 2287, y = 1432}}
(gdb) print resize.r
$14 = {min = {x = 0, y = 0}, max = {x = 2556, y = 1409}}
(gdb)

Aha! The value of resize.max.y should leap out to you as the value of p.y when the segfault was encountered. That is probably about as close to a "smoking gun" as we are going to get. A very conservative patch would perform the operations in screenresize without releasing the lock:

        gscreen->clipr = ZR;
-       qunlock(&drawlock);
-
-       screenresize(r);
-
-       qlock(&drawlock);
+       screenresizelocked(r);
        wl->dirty = 1;

where screenresizelocked is just screenresize with the calls to qlock(&drawlock) and qunlock(&drawlock) removed. This is a very mechanical way to fix the issue without changing the behavior of the program.

However, I think when we change software, we should try to make it easier to maintain the future; the change should make it easier to read, and/or harder to make mistakes. I reached out to the 9front mailing list to discuss the issue. Ultimately, the fix agreed upon moved all of the state management into the screenresize function:

--- a/gui-wl/wl-screen.c
+++ b/gui-wl/wl-screen.c
@@ -62,32 +62,13 @@
 	wl_surface_commit(wl->surface);
 }
 
-void  _screenresize(Rectangle);
-
 void
 wlresize(Wlwin *wl, int x, int y)
 {
 	Rectangle r;
 
-	wl->dx = x;
-	wl->dy = y;
-
-	qlock(&drawlock);
-	wlallocbuffer(wl);
-	r = Rect(0, 0, wl->dx, wl->dy);
-	if(gscreen != nil)
-		freememimage(gscreen);
-	gscreen = allocmemimage(r, XRGB32);
-	gscreen->clipr = ZR;
-	qunlock(&drawlock);
-
+	r = Rect(0, 0, x, y);
 	screenresize(r);
-
-	qlock(&drawlock);
-	wl->dirty = 1;
-	wl->r = r;
-	wlflush(wl);
-	qunlock(&drawlock);
 }
 
 void
@@ -166,6 +147,14 @@
 void
 screensize(Rectangle r, ulong chan)
 {
+	gwin->dx = Dx(r);
+	gwin->dy = Dy(r);
+
+	wlallocbuffer(gwin);
+	if(gscreen != nil)
+		freememimage(gscreen);
+	gscreen = allocmemimage(r, chan);
+	gscreen->clipr = ZR;
 	flushmemscreen(r);
 }
 
--

this function is called by the dedicated resizeproc thread in kern/term.c, which is woken up by the call to screenresize, and which was racing with the wlresize callback before this patch.