Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

random tigervnc freezes with 100% cpu utilisation #1077

Closed
balwierz opened this issue Aug 17, 2020 · 13 comments
Closed

random tigervnc freezes with 100% cpu utilisation #1077

balwierz opened this issue Aug 17, 2020 · 13 comments
Labels
bug Something isn't working

Comments

@balwierz
Copy link

VNC server display gets randomly frozen. Seems to accept no input, no refreshing.
It happened a couple of times, always during active work after a longer time of vncserver running.
Twice, after a longer while (10min+ but not sure exactly), a freeze was gone and I was able to return to work without any discernible problems.
Xtigervnc causes 100% CPU utilisation.
Other users of the same server (all using tigervnc viewer for Mac) did not encounter such problems.

  • OS: Debian testing
  • tigervnc server version 1.10.1 (dfsg-6 amd64)
  • Clients: tigervncviewer (Arch Linux. I checked the two most recent version), TightVCN (windows)

Strace shows the following displayed at infinitum:

[pid 3522168] --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
[pid 3522168] rt_sigreturn({mask=[]})   = 8
[pid 3522168] writev(20<UNIX:[327332923->327327076,@"/tmp/.X11-unix/X2"]>, [{iov_base="\34\0\231\376\2\0 \0q\306\10\0\16ZL\326\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=32}], 1) = 32
[pid 3522168] writev(6<UNIX:[327254006->327327070,@"/tmp/.X11-unix/X2"]>, [{iov_base="\37\253\vB\0\0\0\0\2\0 \0F\0\0\0J\0\0\0q\306\10\0\20\234\235\3761V\0\0", iov_len=32}], 1) = 32
[pid 3522168] --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
[pid 3522168] rt_sigreturn({mask=[]})   = 32

Socket /tmp/.X11-unix/X2 exists.

gdb backtrace

#0  0x00005631fea424c8 in dixLookupProperty (result=result@entry=0x7fff4f13ab10, pWin=pWin@entry=0x563200b7e4a0, propertyName=propertyName@entry=308152, client=client@entry=0x563200523a40, access_mode=access_mode@entry=2)
    at ../../../../unix/xserver/dix/property.c:99
        pProp = 0x56320716be50
        rc = 8
#1  0x00005631fea42840 in dixChangeWindowProperty (pClient=0x563200523a40, pWin=0x563200b7e4a0, property=property@entry=308152, type=type@entry=74, format=format@entry=8, mode=mode@entry=0, len=58, value=0x56320139a9c0, sendevent=1)
    at ../../../../unix/xserver/dix/property.c:269
        pProp = 0x7fff4f13ab98
        savedProp = <optimized out>
        sizeInBytes = 1
        totalSize = 58
        rc = <optimized out>
        data = <optimized out>
        access_mode = 2
#2  0x00005631fe9d7aa4 in vncConvertSelection (client=0x5632008dfff0, selection=70, target=74, property=308152, requestor=2097154, time=0, data=0x56320139a9c0 "dpkg-query -Wf '${Installed-Size}\\t${Package}\\n' | sort -n")
    at ../../../../../unix/xserver/hw/vnc/vncSelection.c:380
        pSel = 0x563200d56880
        pWin = 0x563200b7e4a0
        rc = 0
        realProperty = 308152
        event = {u = {u = {type = 31 '\037', detail = 171 '\253', sequenceNumber = 16907}, keyButtonPointer = {pad00 = 1108060959, time = 0, root = 2097154, event = 70, child = 74, rootX = -19527, rootY = 4, eventX = -25584, eventY = -355,
              state = 22065, sameScreen = 0 '\000', pad1 = 0 '\000'}, enterLeave = {pad00 = 1108060959, time = 0, root = 2097154, event = 70, child = 74, rootX = -19527, rootY = 4, eventX = -25584, eventY = -355, state = 22065,
              mode = 0 '\000', flags = 0 '\000'}, focus = {pad00 = 1108060959, window = 0, mode = 2 '\002', pad1 = 0 '\000', pad2 = 32 ' ', pad3 = 0 '\000'}, expose = {pad00 = 1108060959, window = 0, x = 2, y = 32, width = 70, height = 0,
              count = 74, pad2 = 0}, graphicsExposure = {pad00 = 1108060959, drawable = 0, x = 2, y = 32, width = 70, height = 0, minorEvent = 74, count = 0, majorEvent = 185 '\271', pad1 = 179 '\263', pad2 = 4 '\004', pad3 = 0 '\000'},
            noExposure = {pad00 = 1108060959, drawable = 0, minorEvent = 2, majorEvent = 32 ' ', bpad = 0 '\000'}, visibility = {pad00 = 1108060959, window = 0, state = 2 '\002', pad1 = 0 '\000', pad2 = 32 ' ', pad3 = 0 '\000'},
            createNotify = {pad00 = 1108060959, parent = 0, window = 2097154, x = 70, y = 0, width = 74, height = 0, borderWidth = 46009, override = 4 '\004', bpad = 0 '\000'}, destroyNotify = {pad00 = 1108060959, event = 0,
              window = 2097154}, unmapNotify = {pad00 = 1108060959, event = 0, window = 2097154, fromConfigure = 70 'F', pad1 = 0 '\000', pad2 = 0 '\000', pad3 = 0 '\000'}, mapNotify = {pad00 = 1108060959, event = 0, window = 2097154,
              override = 70 'F', pad1 = 0 '\000', pad2 = 0 '\000', pad3 = 0 '\000'}, mapRequest = {pad00 = 1108060959, parent = 0, window = 2097154}, reparent = {pad00 = 1108060959, event = 0, window = 2097154, parent = 70, x = 74, y = 0,
              override = 185 '\271', pad1 = 179 '\263', pad2 = 4 '\004', pad3 = 0 '\000'}, configureNotify = {pad00 = 1108060959, event = 0, window = 2097154, aboveSibling = 70, x = 74, y = 0, width = 46009, height = 4,
              borderWidth = 39952, override = 157 '\235', bpad = 254 '\376'}, configureRequest = {pad00 = 1108060959, parent = 0, window = 2097154, sibling = 70, x = 74, y = 0, width = 46009, height = 4, borderWidth = 39952,
              valueMask = 65181, pad1 = 22065}, gravity = {pad00 = 1108060959, event = 0, window = 2097154, x = 70, y = 0, pad1 = 74, pad2 = 308153, pad3 = 4271741968, pad4 = 22065}, resizeRequest = {pad00 = 1108060959, window = 0,
              width = 2, height = 32}, circulate = {pad00 = 1108060959, event = 0, window = 2097154, parent = 70, place = 74 'J', pad1 = 0 '\000', pad2 = 0 '\000', pad3 = 0 '\000'}, property = {pad00 = 1108060959, window = 0,
              atom = 2097154, time = 70, state = 74 'J', pad1 = 0 '\000', pad2 = 0}, selectionClear = {pad00 = 1108060959, time = 0, window = 2097154, atom = 70}, selectionRequest = {pad00 = 1108060959, time = 0, owner = 2097154,
              requestor = 70, selection = 74, target = 308153, property = 4271741968}, selectionNotify = {pad00 = 1108060959, time = 0, requestor = 2097154, selection = 70, target = 74, property = 308153}, colormap = {pad00 = 1108060959,
              window = 0, colormap = 2097154, new = 70 'F', state = 0 '\000', pad1 = 0 '\000', pad2 = 0 '\000'}, mappingNotify = {pad00 = 1108060959, request = 0 '\000', firstKeyCode = 0 '\000', count = 0 '\000', pad1 = 0 '\000'},
            clientMessage = {pad00 = 1108060959, window = 0, u = {l = {type = 2097154, longs0 = 70, longs1 = 74, longs2 = 308153, longs3 = -23225328, longs4 = 22065}, s = {type = 2097154, shorts0 = 70, shorts1 = 0, shorts2 = 74,
                  shorts3 = 0, shorts4 = -19527, shorts5 = 4, shorts6 = -25584, shorts7 = -355, shorts8 = 22065, shorts9 = 0}, b = {type = 2097154, bytes = "F\000\000\000J\000\000\000\271\263\004\000\020\234\235\376\061V\000"}}}}}
#3  0x00005631fe9d8872 in vncHandleClipboardData (data=0x56320139a9c0 "dpkg-query -Wf '${Installed-Size}\\t${Package}\\n' | sort -n") at ../../../../../unix/xserver/hw/vnc/vncSelection.c:174
        rc = <optimized out>
        event = {u = {u = {type = 144 '\220', detail = 195 '\303', sequenceNumber = 143}, keyButtonPointer = {pad00 = 9421712, time = 22066, root = 12582944, event = 0, child = 1326689464, rootX = 32767, rootY = 0, eventX = 20064,
              eventY = 177, state = 0, sameScreen = 0 '\000', pad1 = 0 '\000'}, enterLeave = {pad00 = 9421712, time = 22066, root = 12582944, event = 0, child = 1326689464, rootX = 32767, rootY = 0, eventX = 20064, eventY = 177, state = 0,
              mode = 0 '\000', flags = 0 '\000'}, focus = {pad00 = 9421712, window = 22066, mode = 32 ' ', pad1 = 0 '\000', pad2 = 192 '\300', pad3 = 0 '\000'}, expose = {pad00 = 9421712, window = 22066, x = 32, y = 192, width = 0,
              height = 0, count = 44216, pad2 = 20243}, graphicsExposure = {pad00 = 9421712, drawable = 22066, x = 32, y = 192, width = 0, height = 0, minorEvent = 44216, count = 20243, majorEvent = 255 '\377', pad1 = 127 '\177',
              pad2 = 0 '\000', pad3 = 0 '\000'}, noExposure = {pad00 = 9421712, drawable = 22066, minorEvent = 32, majorEvent = 192 '\300', bpad = 0 '\000'}, visibility = {pad00 = 9421712, window = 22066, state = 32 ' ', pad1 = 0 '\000',
              pad2 = 192 '\300', pad3 = 0 '\000'}, createNotify = {pad00 = 9421712, parent = 22066, window = 12582944, x = 0, y = 0, width = 44216, height = 20243, borderWidth = 32767, override = 0 '\000', bpad = 0 '\000'},
            destroyNotify = {pad00 = 9421712, event = 22066, window = 12582944}, unmapNotify = {pad00 = 9421712, event = 22066, window = 12582944, fromConfigure = 0 '\000', pad1 = 0 '\000', pad2 = 0 '\000', pad3 = 0 '\000'}, mapNotify = {
              pad00 = 9421712, event = 22066, window = 12582944, override = 0 '\000', pad1 = 0 '\000', pad2 = 0 '\000', pad3 = 0 '\000'}, mapRequest = {pad00 = 9421712, parent = 22066, window = 12582944}, reparent = {pad00 = 9421712,
              event = 22066, window = 12582944, parent = 0, x = -21320, y = 20243, override = 255 '\377', pad1 = 127 '\177', pad2 = 0 '\000', pad3 = 0 '\000'}, configureNotify = {pad00 = 9421712, event = 22066, window = 12582944,
              aboveSibling = 0, x = -21320, y = 20243, width = 32767, height = 0, borderWidth = 20064, override = 177 '\261', bpad = 0 '\000'}, configureRequest = {pad00 = 9421712, parent = 22066, window = 12582944, sibling = 0,
              x = -21320, y = 20243, width = 32767, height = 0, borderWidth = 20064, valueMask = 177, pad1 = 0}, gravity = {pad00 = 9421712, event = 22066, window = 12582944, x = 0, y = 0, pad1 = 1326689464, pad2 = 32767, pad3 = 11619936,
              pad4 = 0}, resizeRequest = {pad00 = 9421712, window = 22066, width = 32, height = 192}, circulate = {pad00 = 9421712, event = 22066, window = 12582944, parent = 0, place = 184 '\270', pad1 = 172 '\254', pad2 = 19 '\023',
              pad3 = 79 'O'}, property = {pad00 = 9421712, window = 22066, atom = 12582944, time = 0, state = 184 '\270', pad1 = 172 '\254', pad2 = 20243}, selectionClear = {pad00 = 9421712, time = 22066, window = 12582944, atom = 0},
            selectionRequest = {pad00 = 9421712, time = 22066, owner = 12582944, requestor = 0, selection = 1326689464, target = 32767, property = 11619936}, selectionNotify = {pad00 = 9421712, time = 22066, requestor = 12582944,
              selection = 0, target = 1326689464, property = 32767}, colormap = {pad00 = 9421712, window = 22066, colormap = 12582944, new = 0 '\000', state = 0 '\000', pad1 = 0 '\000', pad2 = 0 '\000'}, mappingNotify = {pad00 = 9421712,
              request = 50 '2', firstKeyCode = 86 'V', count = 0 '\000', pad1 = 0 '\000'}, clientMessage = {pad00 = 9421712, window = 22066, u = {l = {type = 12582944, longs0 = 0, longs1 = 1326689464, longs2 = 32767, longs3 = 11619936,
                  longs4 = 0}, s = {type = 12582944, shorts0 = 0, shorts1 = 0, shorts2 = -21320, shorts3 = 20243, shorts4 = 32767, shorts5 = 0, shorts6 = 20064, shorts7 = 177, shorts8 = 0, shorts9 = 0}, b = {type = 12582944,
                  bytes = "\000\000\000\000\270\254\023O\377\177\000\000`N\261\000\000\000\000"}}}}}
#4  0x00005631fe9da90b in XserverDesktop::requestClipboard (this=<optimized out>) at ../../../../../unix/xserver/hw/vnc/XserverDesktop.cc:184
No locals.
#5  0x00005631fe9cfb66 in vncRequestClipboard () at ../../../../../unix/xserver/hw/vnc/vncExtInit.cc:291
        scr = <optimized out>
#6  0x00005631fe9d79a4 in vncConvertSelection (client=client@entry=0x5632008fc390, selection=70, target=<optimized out>, property=476, requestor=12582944, time=3594488609, data=0x0) at ../../../../../unix/xserver/hw/vnc/vncSelection.c:360
        vdt = <optimized out>
        pSel = 0x563200d56880
        pWin = 0x563201236d50
        rc = <optimized out>
        realProperty = <optimized out>
        event = {u = {u = {type = 144 '\220', detail = 195 '\303', sequenceNumber = 143}, keyButtonPointer = {pad00 = 9421712, time = 22066, root = 12582944, event = 0, child = 1326689600, rootX = 32767, rootY = 0, eventX = 19256,
              eventY = -334, state = 22065, sameScreen = 0 '\000', pad1 = 0 '\000'}, enterLeave = {pad00 = 9421712, time = 22066, root = 12582944, event = 0, child = 1326689600, rootX = 32767, rootY = 0, eventX = 19256, eventY = -334,
              state = 22065, mode = 0 '\000', flags = 0 '\000'}, focus = {pad00 = 9421712, window = 22066, mode = 32 ' ', pad1 = 0 '\000', pad2 = 192 '\300', pad3 = 0 '\000'}, expose = {pad00 = 9421712, window = 22066, x = 32, y = 192,
              width = 0, height = 0, count = 44352, pad2 = 20243}, graphicsExposure = {pad00 = 9421712, drawable = 22066, x = 32, y = 192, width = 0, height = 0, minorEvent = 44352, count = 20243, majorEvent = 255 '\377',
              pad1 = 127 '\177', pad2 = 0 '\000', pad3 = 0 '\000'}, noExposure = {pad00 = 9421712, drawable = 22066, minorEvent = 32, majorEvent = 192 '\300', bpad = 0 '\000'}, visibility = {pad00 = 9421712, window = 22066, state = 32 ' ',
              pad1 = 0 '\000', pad2 = 192 '\300', pad3 = 0 '\000'}, createNotify = {pad00 = 9421712, parent = 22066, window = 12582944, x = 0, y = 0, width = 44352, height = 20243, borderWidth = 32767, override = 0 '\000',
              bpad = 0 '\000'}, destroyNotify = {pad00 = 9421712, event = 22066, window = 12582944}, unmapNotify = {pad00 = 9421712, event = 22066, window = 12582944, fromConfigure = 0 '\000', pad1 = 0 '\000', pad2 = 0 '\000',
              pad3 = 0 '\000'}, mapNotify = {pad00 = 9421712, event = 22066, window = 12582944, override = 0 '\000', pad1 = 0 '\000', pad2 = 0 '\000', pad3 = 0 '\000'}, mapRequest = {pad00 = 9421712, parent = 22066, window = 12582944},
            reparent = {pad00 = 9421712, event = 22066, window = 12582944, parent = 0, x = -21184, y = 20243, override = 255 '\377', pad1 = 127 '\177', pad2 = 0 '\000', pad3 = 0 '\000'}, configureNotify = {pad00 = 9421712, event = 22066,
              window = 12582944, aboveSibling = 0, x = -21184, y = 20243, width = 32767, height = 0, borderWidth = 19256, override = 178 '\262', bpad = 254 '\376'}, configureRequest = {pad00 = 9421712, parent = 22066, window = 12582944,
              sibling = 0, x = -21184, y = 20243, width = 32767, height = 0, borderWidth = 19256, valueMask = 65202, pad1 = 22065}, gravity = {pad00 = 9421712, event = 22066, window = 12582944, x = 0, y = 0, pad1 = 1326689600,
              pad2 = 32767, pad3 = 4273097528, pad4 = 22065}, resizeRequest = {pad00 = 9421712, window = 22066, width = 32, height = 192}, circulate = {pad00 = 9421712, event = 22066, window = 12582944, parent = 0, place = 64 '@',
              pad1 = 173 '\255', pad2 = 19 '\023', pad3 = 79 'O'}, property = {pad00 = 9421712, window = 22066, atom = 12582944, time = 0, state = 64 '@', pad1 = 173 '\255', pad2 = 20243}, selectionClear = {pad00 = 9421712, time = 22066,
              window = 12582944, atom = 0}, selectionRequest = {pad00 = 9421712, time = 22066, owner = 12582944, requestor = 0, selection = 1326689600, target = 32767, property = 4273097528}, selectionNotify = {pad00 = 9421712,
              time = 22066, requestor = 12582944, selection = 0, target = 1326689600, property = 32767}, colormap = {pad00 = 9421712, window = 22066, colormap = 12582944, new = 0 '\000', state = 0 '\000', pad1 = 0 '\000', pad2 = 0 '\000'},
            mappingNotify = {pad00 = 9421712, request = 50 '2', firstKeyCode = 86 'V', count = 0 '\000', pad1 = 0 '\000'}, clientMessage = {pad00 = 9421712, window = 22066, u = {l = {type = 12582944, longs0 = 0, longs1 = 1326689600,
                  longs2 = 32767, longs3 = -21869768, longs4 = 22065}, s = {type = 12582944, shorts0 = 0, shorts1 = 0, shorts2 = -21184, shorts3 = 20243, shorts4 = 32767, shorts5 = 0, shorts6 = 19256, shorts7 = -334, shorts8 = 22065,
                  shorts9 = 0}, b = {type = 12582944, bytes = "\000\000\000\000@\255\023O\377\177\000\000\070K\262\376\061V\000"}}}}}
#7  0x00005631fe9d846a in vncProcConvertSelection (client=0x5632008fc390) at ../../../../../unix/xserver/hw/vnc/vncSelection.c:425
        paramsOkay = <optimized out>
        pWin = 0x563201236d50
        pSel = 0x563200d56880
        rc = 0
        stuff = <optimized out>
#8  0x00005631fea23533 in Dispatch () at ../../../../unix/xserver/dix/dispatch.c:478
        result = <optimized out>
        client = 0x5632008fc390
        start_tick = 27050
#9  0x00005631fea274b4 in dix_main (argc=19, argv=0x7fff4f13af38, envp=<optimized out>) at ../../../../unix/xserver/dix/main.c:276
        i = <optimized out>
        alwaysCheckForInput = {0, 1}
#10 0x00007f23e0796cca in __libc_start_main (main=0x5631fe8fba20 <main>, argc=19, argv=0x7fff4f13af38, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fff4f13af28) at ../csu/libc-start.c:308
        self = <optimized out>
        result = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {0, 889761983230163835, 94772724224112, 0, 0, 0, 6900766666193681275, 6808647058819562363}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x13, 0x7fff4f13af38}, data = {prev = 0x0,
              cleanup = 0x0, canceltype = 19}}}
        not_first_call = <optimized out>
#11 0x00005631fe8fd09a in _start () at /usr/include/c++/9/bits/stl_tree.h:211
@CendioOssman
Copy link
Member

That's in the clipboard code, so it could be that it has gotten in to some fight with an application.

Could you add -Log Selection:stderr:100 to your server command line and see what the log file says next time this happens? It will likely start spamming the same set of lines over and over.

@MarkMielke
Copy link
Contributor

What are you using as a desktop environment within the x.org session? Is it KDE?

@balwierz
Copy link
Author

balwierz commented Aug 24, 2020

@MarkMielke: I am using LxQt, but it happened with MATE as well (server side).
@CendioOssman: I do have autocutsel -fork running for clipboard content sharing, so it might be the culprit. autocutsel doesn't cause 100% CPU utilisation thought.

@CendioOssman
Copy link
Member

Given that it is a clipboard command it does indeed sound suspect. However it's description talks about cut buffers, not clipboard. So it shouldn't be screwing with Xvnc.

Did you manage to get that extra logging?

@balwierz
Copy link
Author

I removed autocutsel -fork from my .xtartup and no I got no freezes since then.
When I start with -Log Selection:stderr:100 the log file is flooded with QSystemTrayIcon::setVisible: No Icon set.

@MarkMielke
Copy link
Contributor

I wonder if the log file message is a second symptom rather than a cause.

The reason I mentioned KDE, is because KDE's Klipper has a "Prevent empty clipboard" option that has previously caused us a similar issue. We just turned it off as part of KDE configuration, and I think it might be fixed now. But, at the time - certain scenarios would result some sort of race with each feature fighting the other feature. The reference to QSystemTrayIcon makes me think KDE might be involved - but I'm not aware of whether Klipper is used by LxQt. Possibly autocutsel -fork has the same competitive behaviour with TigerVNC as Klipper with "Prevent empty clipboard" does?

@balwierz
Copy link
Author

balwierz commented Sep 1, 2020

Thanks for your comments.

I am getting this line early at startup:

Selection:   Selection owner change for CLIPBOARD_MANAGER

Later when I select some text in the remote session:

 Selection:   Selection owner change for PRIMARY
 Selection:   Got clipboard notification, probing for formats
 Selection:   Requesting TARGETS for PRIMARY selection
 Selection:   Selection notification for PRIMARY (target TARGETS, property
              TARGETS, type ATOM)
 Selection:   Compatible format found, notifying clients
 Selection:   Got request for local clipboard, re-probing formats
 Selection:   Requesting TARGETS for PRIMARY selection
 Selection:   Selection notification for PRIMARY (target TARGETS, property
              TARGETS, type ATOM)
 Selection:   Requesting UTF8_STRING for PRIMARY selection
 Selection:   Selection notification for PRIMARY (target UTF8_STRING, property
              UTF8_STRING, type UTF8_STRING)
 Selection:   Sending clipboard to clients (5 bytes)

When I start autocutsel from command line:

 Selection:   Got request for local clipboard, re-probing formats
 Selection:   Requesting TARGETS for CLIPBOARD selection
 Selection:   Selection notification for CLIPBOARD (target TARGETS, property
              TARGETS, type ATOM)
 Selection:   Requesting UTF8_STRING for CLIPBOARD selection
 Selection:   Selection notification for CLIPBOARD (target UTF8_STRING,
              property UTF8_STRING, type UTF8_STRING)
 Selection:   Sending clipboard to clients (797 bytes)

And finally, when I start klipper from command line I am getting a stream of QSystemTrayIcon::setVisible: No Icon set

@CendioOssman
Copy link
Member

But no more "Selection" lines?

I don't suppose you can see if this happens with stable Debian?

@balwierz
Copy link
Author

balwierz commented Mar 3, 2021

I was not using TigerVNC recently, but I think I copied all "Selection" lines.
No, I don't have a Debian stable installation to test.

@CendioOssman
Copy link
Member

Very odd. I would expect that if it is stuck in some clipboard war it would be spamming out lines about it.

Someone with access to a system like yours would need to take a look and see if they can reproduce this and figure out how to get some traces.

@peskdale
Copy link

peskdale commented Aug 19, 2021

So this same issue with autocutsel seems to have been happening to me since upgrading to Debian bullseye (neé testing) earlier this week. I'm running tigervnc server 1.11.0+dfsg-2.

When the server is running normally, these same two lines are added to the log repeatedly:

Thu Aug 19 07:22:00 2021
 Selection:   Selection request for CLIPBOARD (type UTF8_STRING)
 Selection:   Requesting clipboard data from client

Thu Aug 19 07:22:01 2021
 Selection:   Selection request for CLIPBOARD (type UTF8_STRING)
 Selection:   Requesting clipboard data from client

After a prolonged period of time if I then try to connect to the server, it freezes up and uses 100% CPU. The log now shows this:

Thu Aug 19 07:22:02 2021
 Selection:   Selection request for CLIPBOARD (type UTF8_STRING)
 Selection:   Requesting clipboard data from client
 Selection:   Remote clipboard announced, grabbing local ownership
 Selection:   Grabbed PRIMARY selection
 Selection:   Grabbed CLIPBOARD selection
 Selection:   Selection request for CLIPBOARD (type UTF8_STRING)
 Selection:   Requesting clipboard data from client
 Selection:   Got remote clipboard data, sending to X11 clients
 Selection:   Sending data for selection request for CLIPBOARD (type UTF8_STRING)
 Selection:   Sending data for selection request for CLIPBOARD (type UTF8_STRING)
 Selection:   Sending data for selection request for CLIPBOARD (type UTF8_STRING)
 Selection:   Sending data for selection request for CLIPBOARD (type UTF8_STRING)

The last line repeats for approx 10,000 lines, interspersed across about a minute of timestamps.

Once CPU activity has returned to idle, server is responsive again, and no further log messages appear until I reconnect a client.
The next log message on reconnect is

Thu Aug 19 07:30:04 2021
 Selection:   Remote clipboard announced, grabbing local ownership
 Selection:   Grabbed PRIMARY selection
 Selection:   Grabbed CLIPBOARD selection

The log file then starts repeating the selection requests again as before, even if the client is closed.

Will try to explore the issue more this weekend, but suggestions welcome. It seems like there is a build up of selection requests while the server is idle, that then all get responded to at once when a client connects, causing the lock-up.

@peskdale
Copy link

This seems likely to be a wider issue with autocutsel - this issue for xrdp sounds almost identical to what I am experiencing.

neutrinolabs/xrdp#1590

@CendioOssman
Copy link
Member

Great, I think that gave me a bit more insight in to what's happening here.

The good news is that it got fixed in 49122f6. So try a pre-release build, or apply that patch to your builds, and the bug should go away.

@CendioOssman CendioOssman added the bug Something isn't working label Aug 26, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants