Failures in output without adding sleep delays

RedBearAK commented 1 year ago

I see by the existence of issue #101 (still open as of now), that more than one person has had issues with key presses being missed. I've been kind of dealing with a related problem for a long time, which is that in some situations there seems to be an issue with output from the virtual keyboard suddenly stopping or having gaps.

Adding a sleep delay at certain points in the app I'm using (a keymapper called keyszer, forked from xkeysnail), will almost completely cure this behavior, but not entirely. And the delay in some situations (virtual machines) needs to be so long that it makes the keymapper pretty unusable.

Hoping someone has some insight here on why this kind of thing might happen, and how it might be cured.

Here's an example of what happens. The keymapper can see an input combo and transform it into some other combo, or even a string of characters (including Unicode in various forms) into a set of output keystrokes. So I can set up CapsLock as a hotkey to output the string "You have pressed CapsLock!" into a text editor app window.

But when this problem is occurring, I'll get various kinds of mistakes in the output like:

You have pres You have pressed CapsLock1 You have preCapsLock!

And so on. Just kind of random glitches in what is supposed to be getting "typed" by the virtual keyboard.

Many users of these keymappers never seem to encounter these issues. I seem to encounter them a lot more frequently. Especially in virtual machines, where I've had pretty bad problems with Kubuntu/KDE/X11 and even worse with Ubuntu/GNOME/Wayland.

The problem is not in the creation of the list of keystrokes that the keymapper returns and sends to the virtual keyboard. I can see all the intended keystroke events being logged to a terminal. I can print out the list of keystrokes before they are sent to the output module, and it's always perfect. Some of the keystrokes just seem to vanish and never come out into the focused app window.

One particular spot that has been helpful in reducing this is this function that sends a sync:

    import time

    def __send_sync(self):
        time.sleep(0.05)
        _uinput.syn()

On my main laptop with a bare metal install, this delay only needs to be 0.0001s to be useful. In the VM I'm testing, it needs to be about 0.05s, or things start to go wrong with the output.

Any ideas anyone has to troubleshoot this would be helpful. I've tried to work with the keyszer dev to understand exactly what is going wrong and how to mitigate it, but we've never made much progress.

https://github.com/joshgoebel/keyszer

sezanzeb commented 1 year ago

RedBearAK commented 1 year ago

possibly related: sezanzeb/input-remapper#335

Yes, that does seem very similar. Thanks for the link.

Due to the differences between the projects I'm not sure exactly how the delay I put in that location in keyszer compares.

I notice someone says they need to use a delay of 20ms, which is close to the 0.05s (50ms) I'm needing to use in this VM situation. Unfortunately the way I'm inserting the delay doesn't just affect "macros" but all keystrokes, which means it adds the delay even during normal typing. But I can't seem to make transformed shortcut combos work correctly without the delay.

No one in that thread seems to have any idea exactly what is causing the issue, just that adding a delay is a workaround.

RedBearAK commented 1 year ago

Output from the virtual keyboard appears perfect, pressing Shift before the correct keystrokes and releasing Shift after the other key is pressed/released. But what winds up in the text editor without the long delay is variations of:

you have double-tapped the grave key1
yoU have double-tapped the grave key1

When it should be:

You have double-tapped the Grave key!

evtest output from the virtual keyboard device:

evtest
No device specified, trying to scan all of /dev/input/event*
Not running as root, no devices may be available.
Available devices:
/dev/input/event0:  Power Button
/dev/input/event1:  AT Translated Set 2 keyboard
/dev/input/event2:  VirtualPS/2 VMware VMMouse
/dev/input/event3:  VirtualPS/2 VMware VMMouse
/dev/input/event4:  QEMU QEMU USB Tablet
/dev/input/event5:  spice vdagent tablet
/dev/input/event6:  Keyszer (virtual) Keyboard
Select the device event number [0-6]: 6
Input driver version is 1.0.1
Input device ID: bus 0x3 vendor 0x1 product 0x1 version 0x1
Input device name: "Keyszer (virtual) Keyboard"
Supported events:
  Event type 0 (EV_SYN)
  Event type 1 (EV_KEY)
    Event code 1 (KEY_ESC)
    Event code 2 (KEY_1)
        [snip: hundreds of event codes]
    Event code 700 (?)
  Event type 2 (EV_REL)
    Event code 0 (REL_X)
    Event code 1 (REL_Y)
    Event code 6 (REL_HWHEEL)
    Event code 8 (REL_WHEEL)
    Event code 9 (REL_MISC)
  Event type 21 (EV_FF)
Properties:
Testing ... (interrupt to exit)
Event: time 1676320823.050567, type 1 (EV_KEY), code 28 (KEY_ENTER), value 0
Event: time 1676320823.050567, -------------- SYN_REPORT ------------
Event: time 1676320831.889638, type 1 (EV_KEY), code 42 (KEY_LEFTSHIFT), value 1
Event: time 1676320831.889638, -------------- SYN_REPORT ------------
Event: time 1676320831.889803, type 1 (EV_KEY), code 21 (KEY_Y), value 1
Event: time 1676320831.889803, -------------- SYN_REPORT ------------
Event: time 1676320831.889873, type 1 (EV_KEY), code 21 (KEY_Y), value 0
Event: time 1676320831.889873, -------------- SYN_REPORT ------------
Event: time 1676320831.889947, type 1 (EV_KEY), code 42 (KEY_LEFTSHIFT), value 0
Event: time 1676320831.889947, -------------- SYN_REPORT ------------
Event: time 1676320831.890088, type 1 (EV_KEY), code 24 (KEY_O), value 1
Event: time 1676320831.890088, -------------- SYN_REPORT ------------
Event: time 1676320831.890186, type 1 (EV_KEY), code 24 (KEY_O), value 0
Event: time 1676320831.890186, -------------- SYN_REPORT ------------
Event: time 1676320831.890322, type 1 (EV_KEY), code 22 (KEY_U), value 1
Event: time 1676320831.890322, -------------- SYN_REPORT ------------
Event: time 1676320831.890455, type 1 (EV_KEY), code 22 (KEY_U), value 0
Event: time 1676320831.890455, -------------- SYN_REPORT ------------
Event: time 1676320831.890562, type 1 (EV_KEY), code 57 (KEY_SPACE), value 1
Event: time 1676320831.890562, -------------- SYN_REPORT ------------
Event: time 1676320831.890662, type 1 (EV_KEY), code 57 (KEY_SPACE), value 0
Event: time 1676320831.890662, -------------- SYN_REPORT ------------
Event: time 1676320831.890796, type 1 (EV_KEY), code 35 (KEY_H), value 1
Event: time 1676320831.890796, -------------- SYN_REPORT ------------
Event: time 1676320831.890903, type 1 (EV_KEY), code 35 (KEY_H), value 0
Event: time 1676320831.890903, -------------- SYN_REPORT ------------
Event: time 1676320831.891020, type 1 (EV_KEY), code 30 (KEY_A), value 1
Event: time 1676320831.891020, -------------- SYN_REPORT ------------
Event: time 1676320831.891071, type 1 (EV_KEY), code 30 (KEY_A), value 0
Event: time 1676320831.891071, -------------- SYN_REPORT ------------
Event: time 1676320831.891173, type 1 (EV_KEY), code 47 (KEY_V), value 1
Event: time 1676320831.891173, -------------- SYN_REPORT ------------
Event: time 1676320831.891303, type 1 (EV_KEY), code 47 (KEY_V), value 0
Event: time 1676320831.891303, -------------- SYN_REPORT ------------
Event: time 1676320831.891437, type 1 (EV_KEY), code 18 (KEY_E), value 1
Event: time 1676320831.891437, -------------- SYN_REPORT ------------
Event: time 1676320831.891544, type 1 (EV_KEY), code 18 (KEY_E), value 0
Event: time 1676320831.891544, -------------- SYN_REPORT ------------
Event: time 1676320831.891649, type 1 (EV_KEY), code 57 (KEY_SPACE), value 1
Event: time 1676320831.891649, -------------- SYN_REPORT ------------
Event: time 1676320831.891852, type 1 (EV_KEY), code 57 (KEY_SPACE), value 0
Event: time 1676320831.891852, -------------- SYN_REPORT ------------
Event: time 1676320831.891995, type 1 (EV_KEY), code 32 (KEY_D), value 1
Event: time 1676320831.891995, -------------- SYN_REPORT ------------
Event: time 1676320831.892105, type 1 (EV_KEY), code 32 (KEY_D), value 0
Event: time 1676320831.892105, -------------- SYN_REPORT ------------
Event: time 1676320831.892254, type 1 (EV_KEY), code 24 (KEY_O), value 1
Event: time 1676320831.892254, -------------- SYN_REPORT ------------
Event: time 1676320831.892406, type 1 (EV_KEY), code 24 (KEY_O), value 0
Event: time 1676320831.892406, -------------- SYN_REPORT ------------
Event: time 1676320831.892554, type 1 (EV_KEY), code 22 (KEY_U), value 1
Event: time 1676320831.892554, -------------- SYN_REPORT ------------
Event: time 1676320831.892673, type 1 (EV_KEY), code 22 (KEY_U), value 0
Event: time 1676320831.892673, -------------- SYN_REPORT ------------
Event: time 1676320831.892831, type 1 (EV_KEY), code 48 (KEY_B), value 1
Event: time 1676320831.892831, -------------- SYN_REPORT ------------
Event: time 1676320831.892938, type 1 (EV_KEY), code 48 (KEY_B), value 0
Event: time 1676320831.892938, -------------- SYN_REPORT ------------
Event: time 1676320831.893066, type 1 (EV_KEY), code 38 (KEY_L), value 1
Event: time 1676320831.893066, -------------- SYN_REPORT ------------
Event: time 1676320831.893163, type 1 (EV_KEY), code 38 (KEY_L), value 0
Event: time 1676320831.893163, -------------- SYN_REPORT ------------
Event: time 1676320831.893289, type 1 (EV_KEY), code 18 (KEY_E), value 1
Event: time 1676320831.893289, -------------- SYN_REPORT ------------
Event: time 1676320831.893425, type 1 (EV_KEY), code 18 (KEY_E), value 0
Event: time 1676320831.893425, -------------- SYN_REPORT ------------
Event: time 1676320831.893588, type 1 (EV_KEY), code 12 (KEY_MINUS), value 1
Event: time 1676320831.893588, -------------- SYN_REPORT ------------
Event: time 1676320831.893716, type 1 (EV_KEY), code 12 (KEY_MINUS), value 0
Event: time 1676320831.893716, -------------- SYN_REPORT ------------
Event: time 1676320831.893832, type 1 (EV_KEY), code 20 (KEY_T), value 1
Event: time 1676320831.893832, -------------- SYN_REPORT ------------
Event: time 1676320831.893906, type 1 (EV_KEY), code 20 (KEY_T), value 0
Event: time 1676320831.893906, -------------- SYN_REPORT ------------
Event: time 1676320831.894014, type 1 (EV_KEY), code 30 (KEY_A), value 1
Event: time 1676320831.894014, -------------- SYN_REPORT ------------
Event: time 1676320831.894096, type 1 (EV_KEY), code 30 (KEY_A), value 0
Event: time 1676320831.894096, -------------- SYN_REPORT ------------
Event: time 1676320831.894266, type 1 (EV_KEY), code 25 (KEY_P), value 1
Event: time 1676320831.894266, -------------- SYN_REPORT ------------
Event: time 1676320831.894419, type 1 (EV_KEY), code 25 (KEY_P), value 0
Event: time 1676320831.894419, -------------- SYN_REPORT ------------
Event: time 1676320831.894584, type 1 (EV_KEY), code 25 (KEY_P), value 1
Event: time 1676320831.894584, -------------- SYN_REPORT ------------
Event: time 1676320831.894709, type 1 (EV_KEY), code 25 (KEY_P), value 0
Event: time 1676320831.894709, -------------- SYN_REPORT ------------
Event: time 1676320831.894841, type 1 (EV_KEY), code 18 (KEY_E), value 1
Event: time 1676320831.894841, -------------- SYN_REPORT ------------
Event: time 1676320831.895008, type 1 (EV_KEY), code 18 (KEY_E), value 0
Event: time 1676320831.895008, -------------- SYN_REPORT ------------
Event: time 1676320831.895184, type 1 (EV_KEY), code 32 (KEY_D), value 1
Event: time 1676320831.895184, -------------- SYN_REPORT ------------
Event: time 1676320831.895295, type 1 (EV_KEY), code 32 (KEY_D), value 0
Event: time 1676320831.895295, -------------- SYN_REPORT ------------
Event: time 1676320831.895474, type 1 (EV_KEY), code 57 (KEY_SPACE), value 1
Event: time 1676320831.895474, -------------- SYN_REPORT ------------
Event: time 1676320831.895591, type 1 (EV_KEY), code 57 (KEY_SPACE), value 0
Event: time 1676320831.895591, -------------- SYN_REPORT ------------
Event: time 1676320831.895806, type 1 (EV_KEY), code 20 (KEY_T), value 1
Event: time 1676320831.895806, -------------- SYN_REPORT ------------
Event: time 1676320831.895924, type 1 (EV_KEY), code 20 (KEY_T), value 0
Event: time 1676320831.895924, -------------- SYN_REPORT ------------
Event: time 1676320831.896088, type 1 (EV_KEY), code 35 (KEY_H), value 1
Event: time 1676320831.896088, -------------- SYN_REPORT ------------
Event: time 1676320831.896194, type 1 (EV_KEY), code 35 (KEY_H), value 0
Event: time 1676320831.896194, -------------- SYN_REPORT ------------
Event: time 1676320831.897043, type 1 (EV_KEY), code 18 (KEY_E), value 1
Event: time 1676320831.897043, -------------- SYN_REPORT ------------
Event: time 1676320831.897215, type 1 (EV_KEY), code 18 (KEY_E), value 0
Event: time 1676320831.897215, -------------- SYN_REPORT ------------
Event: time 1676320831.897477, type 1 (EV_KEY), code 57 (KEY_SPACE), value 1
Event: time 1676320831.897477, -------------- SYN_REPORT ------------
Event: time 1676320831.897640, type 1 (EV_KEY), code 57 (KEY_SPACE), value 0
Event: time 1676320831.897640, -------------- SYN_REPORT ------------
Event: time 1676320831.897814, type 1 (EV_KEY), code 42 (KEY_LEFTSHIFT), value 1
Event: time 1676320831.897814, -------------- SYN_REPORT ------------
Event: time 1676320831.897947, type 1 (EV_KEY), code 34 (KEY_G), value 1
Event: time 1676320831.897947, -------------- SYN_REPORT ------------
Event: time 1676320831.898043, type 1 (EV_KEY), code 34 (KEY_G), value 0
Event: time 1676320831.898043, -------------- SYN_REPORT ------------
Event: time 1676320831.898196, type 1 (EV_KEY), code 42 (KEY_LEFTSHIFT), value 0
Event: time 1676320831.898196, -------------- SYN_REPORT ------------
Event: time 1676320831.898414, type 1 (EV_KEY), code 19 (KEY_R), value 1
Event: time 1676320831.898414, -------------- SYN_REPORT ------------
Event: time 1676320831.898545, type 1 (EV_KEY), code 19 (KEY_R), value 0
Event: time 1676320831.898545, -------------- SYN_REPORT ------------
Event: time 1676320831.898728, type 1 (EV_KEY), code 30 (KEY_A), value 1
Event: time 1676320831.898728, -------------- SYN_REPORT ------------
Event: time 1676320831.898838, type 1 (EV_KEY), code 30 (KEY_A), value 0
Event: time 1676320831.898838, -------------- SYN_REPORT ------------
Event: time 1676320831.899035, type 1 (EV_KEY), code 47 (KEY_V), value 1
Event: time 1676320831.899035, -------------- SYN_REPORT ------------
Event: time 1676320831.899146, type 1 (EV_KEY), code 47 (KEY_V), value 0
Event: time 1676320831.899146, -------------- SYN_REPORT ------------
Event: time 1676320831.899380, type 1 (EV_KEY), code 18 (KEY_E), value 1
Event: time 1676320831.899380, -------------- SYN_REPORT ------------
Event: time 1676320831.899512, type 1 (EV_KEY), code 18 (KEY_E), value 0
Event: time 1676320831.899512, -------------- SYN_REPORT ------------
Event: time 1676320831.899752, type 1 (EV_KEY), code 57 (KEY_SPACE), value 1
Event: time 1676320831.899752, -------------- SYN_REPORT ------------
Event: time 1676320831.899904, type 1 (EV_KEY), code 57 (KEY_SPACE), value 0
Event: time 1676320831.899904, -------------- SYN_REPORT ------------
Event: time 1676320831.900102, type 1 (EV_KEY), code 37 (KEY_K), value 1
Event: time 1676320831.900102, -------------- SYN_REPORT ------------
Event: time 1676320831.900249, type 1 (EV_KEY), code 37 (KEY_K), value 0
Event: time 1676320831.900249, -------------- SYN_REPORT ------------
Event: time 1676320831.900415, type 1 (EV_KEY), code 18 (KEY_E), value 1
Event: time 1676320831.900415, -------------- SYN_REPORT ------------
Event: time 1676320831.900526, type 1 (EV_KEY), code 18 (KEY_E), value 0
Event: time 1676320831.900526, -------------- SYN_REPORT ------------
Event: time 1676320831.900676, type 1 (EV_KEY), code 21 (KEY_Y), value 1
Event: time 1676320831.900676, -------------- SYN_REPORT ------------
Event: time 1676320831.900776, type 1 (EV_KEY), code 21 (KEY_Y), value 0
Event: time 1676320831.900776, -------------- SYN_REPORT ------------
Event: time 1676320831.900909, type 1 (EV_KEY), code 42 (KEY_LEFTSHIFT), value 1
Event: time 1676320831.900909, -------------- SYN_REPORT ------------
Event: time 1676320831.901020, type 1 (EV_KEY), code 2 (KEY_1), value 1
Event: time 1676320831.901020, -------------- SYN_REPORT ------------
Event: time 1676320831.901152, type 1 (EV_KEY), code 2 (KEY_1), value 0
Event: time 1676320831.901152, -------------- SYN_REPORT ------------
Event: time 1676320831.901234, type 1 (EV_KEY), code 42 (KEY_LEFTSHIFT), value 0
Event: time 1676320831.901234, -------------- SYN_REPORT ------------
Event: time 1676320831.901485, type 1 (EV_KEY), code 28 (KEY_ENTER), value 1
Event: time 1676320831.901485, -------------- SYN_REPORT ------------
Event: time 1676320831.901647, type 1 (EV_KEY), code 28 (KEY_ENTER), value 0
Event: time 1676320831.901647, -------------- SYN_REPORT ------------

sezanzeb commented 1 year ago

This issue should probably be reported at one of gnomes issue trackers https://gitlab.gnome.org/GNOME, considering you specifically have problems with gnome (https://github.com/gvalkov/python-evdev/issues/186#issuecomment-1427008264), but I don't know which project would be fitting for that.

RedBearAK commented 1 year ago

you specifically have problems with gnome

No, I have had problems with these key sequence unreliability issues in multiple distros, multiple DEs and now, multiple display servers (X11 and Wayland). As far as I know there is nothing about this specific to GNOME. The problem just seems to be quite a bit worse within a couple of the VMs I'm testing. But the host OS is Fedora/X11/GNOME while the VMs are Kubuntu/X11/Plasma and Ubuntu/Wayland/GNOME.

I've also replicated the issue of unreliable macros on other laptops of varying descriptions. Most were less prone to the problem than the Acer laptop I'm usually working on, but it happened on all of them if I tested enough times. Different Linux distros, different desktop environments, different hardware.

If I had a proper concept of what exactly is "receiving" the keystrokes from the virtual keyboard when it's "typing", I might have some idea what direction to go with researching a solution. Is it the kernel input system, or the display server, or the window manager, or the application window itself? Where in the chain might there be some kind of buffer that is mixing up keystrokes, or even losing some of them, when they are issued too quickly?

sezanzeb commented 1 year ago

Do you observe the issue in xev as well?

RedBearAK commented 1 year ago

Do you observe the issue in xev as well?

I'll have to get back to you on that. The xev window is giving me an error in the Wayland/DBus module that gets the window attributes from the GNOME extension. I'll have to find some way of triggering the macro while the xev window is in focus.

But maybe I can get it to work better on the host, in X11. Will update tomorrow if I have time.

Edit: No, this is the first time I've seen an app in X11 fail to report any WM_CLASS and WM_NAME from using xprop on it. Not quite sure how I'll trigger macros for testing unless they're in a keymap that will be active in all application windows by default. We'll see.

RedBearAK commented 1 year ago

@sezanzeb

Preliminary results appear to be the same as with evtest. No problem with the order of the key events being issued. No missing key events. But it's somewhat difficult to test in Wayland because I can't match on the window class. I was able to use "^$" to match in X11. In Wayland I have to start a long macro with another window focused and then quickly click on the xev window.

I'll have to do some filtering of the xev terminal output and see if I can get it to show the kind of errors that appear in the text editor and other apps. I doubt it. I think I tried this before in the past, and what showed in the terminal was always fine.

Edit: No apparent problem with the filtered xev output. Shifted characters are all correct, no failures.

sezanzeb commented 1 year ago

libinput is a library that provides a full input stack for display servers and other applications that need to handle input devices provided by the kernel.

https://gitlab.freedesktop.org/libinput/libinput

So I guess libinput is not the issue, since X11 seems to work fine? But maybe it could be worth asking for more directions there

The arch wiki mentions wev as a xev alternative for wayland (https://wiki.archlinux.org/title/Keyboard_input)

RedBearAK commented 1 year ago

Update: Someone left a note on the libinput issue that this may have something to do with IBus.

IBus does seem to play a large part in the severity of the problem I'm experiencing in the VM, which takes delays of around 100ms in total to have predictable output appear in the application.

But, macros will still fail even when IBus is disabled. Although it only takes 1ms of strategic keystroke delay in order to bring back macro reliability.

So the problem requires two orders of magnitude more "correction" with IBus involved, but still occurs and needs some correction without IBus being involved.

gvalkov / python-evdev

Failures in output without adding sleep delays #187