Multiple Mouse-Events Per Click...?

General Discussion
1

This may well end up moving to GitHub; I’m posting this here for the moment because I’m not yet confident that it’s an engine bug, rather than a bug in my own code, and to find out whether others have encountered something similar before. And if it does turn out to be an issue in my code, then perhaps this thread will prove useful to others.

That said:

I recently received a rather troubling bug-report regarding the demo of A Door to the Mists: the player in question reported that, (as it turned out) about four times out of five, attempting to pick up an object crashed the game!

Looking at the log-output, it seemed that the game was attempting to act on an object that had already been cleaned up. Giving it some thought, one plausible scenario that came to mind was that the game was receiving more than one “mouse-button-up” event per click.

I’m still testing this hypothesis, but there is some corroboration: the player in question reports that they’re using a mouse that’s being polled at a very high rate (500Hz, I believe)–and that switching to a different pointing-device causes the problem to go away!

Specific information:

The problem-mouse is “a decade or more old PS2 Intellimouse”, being polled at 500Hz. This is apparently being done in part via the following Linux kernel option: “(usbhid.mousepoll=2)”.

This setup has apparently not caused problems with other programs in the past.

With “a cheap wireless touchpad (USB)”, polling at 91Hz, the problem does not occur.

The X event tool apparently didn’t show “anything strange or interesting”.

The OS on which this is being run by the player is “Void Linux”.

A test with a simple program counting mouse-events didn’t evince the bug, so it’s still possible that the issue is somewhere in my code.

However, so simple was the test-program that it was likely running at a very, very high frame-rate, so it’s also possible that the bug occurs when the program’s frame-rate is lower than the polling rate of the mouse, or something like that. (On my own machine, the test-program runs at more than 2000fps.)

I’ve requested a trial with a modified version of the test-program, this one using “globalClock.setMode(ClockObject.M_limited)” followed by “globalClock.setFrameRate(50)” to artificially reduce the frame-rate, and am waiting for a response at time of writing.

Has anyone seen anything like this before? Any thoughts?

2

I’ve not seen this before, but would it be an option to collect a verbose debug log that includes base.messenger.toggleVerbose(), plus messages of your game logic, from the user? That would allow you to confirm whether the event is indeed sent twice.

It is theoretically conceivable that the X11 server is sending multiple ButtonRelease, or sending them out of order, or so; use of the xev utility could be used to confirm such behaviour of the mouse or X11 server in general.

3

Hmm… I’ve modified the test-program to include “toggleVerbose”; if the bug occurs in this version, then hopefully the output will help!

However, if the bug doesn’t show up there then doing so might not be useful. :/

(And I don’t want to ask the player to re-download the half-gigabyte game-demo in order to test for me! :/)

4

I think that perhaps the reason lies in the mechanical wear of the click 1 button. This occurs when the contact plate becomes non-elastic and the button begins to double-click. This is a problem with the old mouse.

5

I would love to believe that–but the player reports having no such problems in other programs. :/

(Unless all the programs that they’ve tried since the mechanical wear reached that point have, for one reason or another, not had a problem with multiple mouse-clicks, of course–which is possible.)

I do think that I’ll likely put in some defence against this issue on my end–even if it’s just clearing the “object being looked at” variable after a mouse-up callback, so that a subsequent callback won’t have anything to work with until the next update refreshes the variable.

6

Yes, that’s right, with mechanical wear and tear, there would be problems with other applications that do not exist. Although who knows maybe on your game, the player broke the mouse, I’m not hinting at anything. :slight_smile:

7

Hah, I can hope that it’s not quite that frustrating! XD;

8

All right, I’ve had a response. It’s fairly long, so I am for the most part just going to link to the relevant posts, which include the requested output.

That said… A few things stand out for me:

  1. The bug doesn’t seem to appear in the test-program. Note that in each of the posted output-texts there are forty lines that start with “Test Printout”, correlating presumably with twenty each of presses and releases, which matches with the reported testing procedure.

    • However, it looks like the frame-rate limitation option may have been missed, so we’ll see whether they’re willing to run one more test for me!

  2. The bug seems to vary by mouse and by USB port. What.

  3. The player mentions that mouse sensitivity seems to be lower than expected, perhaps being related to the reported kernel-option in use for mouse-polling.

Here are the relevant posts:
https://forums.tigsource.com/index.php?topic=57649.msg1418386#msg1418386
https://forums.tigsource.com/index.php?topic=57649.msg1418390#msg1418390
https://forums.tigsource.com/index.php?topic=57649.msg1418391#msg1418391

(The second of those contains the requested output, as well as data on the mice being used, I believe. Again, note that this output seems to have been produced without frame-rate limiting; I’m hoping for more output produced with it in effect.)

9

Just to rule this out, but you’re not attaching raw mice to the data graph at the same time as the normal mouse input, right? That could cause double input.

I’m trying to interpret the logs. There’s barely any output but the mouse events so it’s hard to get a sense of reference. Are all the event handlers really being called seconds after all the clicks occur, or is this just due to a lack of sys.stdout.flush()? I’m expecting to see some kind of exception in the output logs marked “bad”; are exceptions not being logged? What does “crash” mean exactly?

10

I don’t think so, but I’d have to check. However, if I were, I would expect to consistently get double-inputs on most machines, my own included, which doesn’t seem to be the case.

I imagine that it’s a lack of “flush”–when I run the test-program on my own machine, executing from the console, I see my test-printouts appearing immediately after each click. I’m not clear on why that’s not happening on the user’s machine, but I don’t have calls for “sys.stdout.flush()”, so I’m very willing to accept that this lack might be the problem!

(My guess is that this happened as a result of the player redirecting the system’s output to a file, rather than letting the console print and then copy-pasting the result. Testing quickly on my machine, I see that doing so produces the result that we see in the player’s output logs: all the test-printouts collected at the end of the file, instead of interleaved with the debug output as expected.)

As I said, for some reason it looks like the bug isn’t appearing in the test-program (yet); as a result, there are no crashes in the output given there.

I’m hoping that the issue will turn up if the player re-tries the test with frame-rate limitation in place.

In the game itself, from what I’m told, the crashes are as follows: the game exits unexpectedly, with an exception indicating that the code is trying to call a method from a variable that has been set to “None” (presumably as a result of the object in question having been cleaned up in response to a previous click-event).

11

All right, I have more information! Specifically, the player who reported this issue has successfully replicated it with a small test-program.

Once again, here is the relevant post, which includes output logs (starting at the heading “Mouse tester 0.3”):
https://forums.tigsource.com/index.php?topic=57649.msg1419210#msg1419210

A few things that I noted:

  • It looks like the issue is related to my KeyMapper module; I imagine that it’s related specifically to the handling of non-keyboard-and-mouse devices.
    • Given this, I’m inclined to wonder whether it’s not related to this old thread, in which I was getting a single phantom mouse-up event that seemed to trace to my graphics tablet.
    • The player in question noted that at least one other program had previously misidentified their keyboard as a gamepad.
  • They seemed to get odd results when pressing certain keyboard keys and then attempting to bind a control. This doesn’t seem to replicate on my own machine.

For reference, here is a screenshot of the testing-program used:

The UI that you see in the right is a slightly-adjusted default KeyMapper UI.

(I imagine that when the player says that they “click[ed] on up”, they mean that they clicked on the button that binds the “up” control in the tester.)

If you want to try the test-program yourself, it should be available via this link:
https://www.dropbox.com/s/y93kvmtky7lplqo/Mouse-Event%20Tester-0.3_manylinux1_x86_64.tar.gz?dl=1

[edit]
I’d forgotten to add a link to the “old thread” that I mentioned. That’s present now, and for convenience, here it is again below. ^^;