Subject: bug#74590: 31.0.50 [scratch/igc branch]; key input sometimes skip fcitx input method preedit box

From: Yikai Zhao <[email-masked]>
Date: Tue, 18 Feb 2025 21:05:52 +0800

Hi,

I have finished bisecting between the two versions, I have identified
that it's this commit that lowers the frequency of the issue:

  commit c425f10a30c96f45fe1ccce423851bf32b8cb8df: Make balancing
buffer intervals optional

Based on the change of this commit, I can also verify that, with the
newest version of feature/igc, when setting igc--balance-intervals to
t, the issue can be reproduced with similar high probability as
before.

I also tried your newest patch, but the issue still happens... I
modified your patch for a little bit to add some more debug info
(timestamps etc.) and recorded a video reproducing the issue. I hope
it helps. See attachments for the modified patch, the screencast video
and the log.

In the video, I typed: c e u i <space> c e u i <space> . Each "c e u
i" should translates to "测试" by fcitx and "<space>" should confirm it.
But note that the second "c" went straight to the emacs buffer. The
video also shows the live log on the left side, maybe it will be
helpful.

Yikai

On Tue, Feb 18, 2025 at 9:45 AM Yikai Zhao <[email-masked]> wrote:
>
> On Tue, Feb 18, 2025 at 3:02 AM Pip Cet <[email-masked]> wrote:
> >
> > "Yikai Zhao" <[email-masked]> writes:
> >
> > > I'm sorry to tell you that the issue still happens with your patch. I
> > > don't see anything abnormal about the printed timestamps when the
> > > issue happens (no unordered timestamps found).
> >
> > Oh no!  It seems I missed some cases, which might explain it, but it's
> > also possible it's an entirely separate issue.  Did it become less
> > frequent, at least?
>
> I'm not sure. As I said, the frequency in the new version without the
> patch is already much lower, so I really cannot say about the
> difference with or without the patch.
>
> > > Now I think maybe what you described is not the same issue that I
> > > encountered. :(
> >
> > Maybe.  If you still have the time, can you try this extended patch
> > instead?
>
> Sure, I will. It will just take some time.
>
> >
> > diff --git a/src/xterm.c b/src/xterm.c
> > index c3137945ac5..52052fcc9c3 100644
> > --- a/src/xterm.c
> > +++ b/src/xterm.c
> > @@ -13040,7 +13040,10 @@ x_dnd_begin_drag_and_drop (struct frame *f, Time time, Atom xaction,
> >                   != event_display->xi2_opcode))
> >             {
> >  #endif
> > -             if (!x_filter_event (event_display, &next_event))
> > +             XEvent event_copy = next_event;
> > +             if (event_copy.type == KeyPress || event_copy.type == KeyRelease)
> > +               event_copy.xkey.time = CurrentTime;
> > +             if (!x_filter_event (event_display, &event_copy))
> >                 handle_one_xevent (event_display,
> >                                    &next_event, &finish, &hold_quit);
> >  #ifdef HAVE_XINPUT2
> > @@ -17892,8 +17895,12 @@ x_filter_event (struct x_display_info *dpyinfo, XEvent *event)
> >     XFilterEvent because that's the one for which the IC
> >     was created.  */
> >
> > +  //usleep (10000);
> >    struct frame *f1;
> >
> > +  if (event->type == KeyPress || event->type == KeyRelease)
> > +    if (event->xkey.time > 1)
> > +      emacs_abort();
> >  #if defined HAVE_XINPUT2 && defined USE_GTK
> >    bool xinput_event = false;
> >    if (dpyinfo->supports_xi2
> > @@ -17976,9 +17983,13 @@ event_handler_gdk (GdkXEvent *gxev, GdkEvent *ev, gpointer data)
> >        /* Filter events for the current X input method.
> >           GTK calls XFilterEvent but not for key press and release,
> >           so we do it here.  */
> > +      XEvent xev_copy;
> > +      xev_copy = *xev;
> > +      fprintf (stderr, "ignoring time %ld\n", (long) xev_copy.xkey.time);
> > +      xev_copy.xkey.time = CurrentTime;
> >        if ((xev->type == KeyPress || xev->type == KeyRelease)
> >           && dpyinfo
> > -         && x_filter_event (dpyinfo, xev))
> > +         && x_filter_event (dpyinfo, &xev_copy))
> >         {
> >           unblock_input ();
> >           return GDK_FILTER_REMOVE;
> > @@ -24131,7 +24142,8 @@ handle_one_xevent (struct x_display_info *dpyinfo,
> >                   copy.xkey.window = xev->event;
> >                   copy.xkey.root = xev->root;
> >                   copy.xkey.subwindow = xev->child;
> > -                 copy.xkey.time = xev->time;
> > +                 fprintf (stderr, "ignoring time %ld\n", (long) xev->time);
> > +                 copy.xkey.time = CurrentTime;
> >                   copy.xkey.state = state;
> >                   xi_convert_button_state (&xev->buttons, &copy.xkey.state);
> >
> > @@ -24189,7 +24201,8 @@ handle_one_xevent (struct x_display_info *dpyinfo,
> >               xkey.window = xev->event;
> >               xkey.root = xev->root;
> >               xkey.subwindow = xev->child;
> > -             xkey.time = xev->time;
> > +             fprintf (stderr, "ignoring time %ld\n", (long) xev->time);
> > +             xkey.time = CurrentTime;
> >               xkey.state = state;
> >               xkey.x = lrint (xev->event_x);
> >               xkey.y = lrint (xev->event_y);
> > @@ -24631,7 +24644,8 @@ handle_one_xevent (struct x_display_info *dpyinfo,
> >               xkey.window = xev->event;
> >               xkey.root = xev->root;
> >               xkey.subwindow = xev->child;
> > -             xkey.time = xev->time;
> > +             fprintf (stderr, "ignoring time %ld\n", (long) xev->time);
> > +             xkey.time = CurrentTime;
> >               xkey.state = xi_convert_event_keyboard_state (xev);
> >               xkey.x = lrint (xev->event_x);
> >               xkey.y = lrint (xev->event_y);
> > @@ -25765,7 +25779,14 @@ XTread_socket (struct terminal *terminal, struct input_event *hold_quit)
> >           /* Input extension key events are filtered inside
> >              handle_one_xevent.  */
> >  #endif
> > -         if (x_filter_event (dpyinfo, &event))
> > +         XEvent event_copy = event;
> > +         if (event_copy.type == KeyPress || event_copy.type == KeyRelease)
> > +           {
> > +             fprintf (stderr, "ignoring time %ld\n", (long) event.xkey.time);
> > +             event_copy.xkey.time = CurrentTime;
> > +           }
> > +
> > +         if (x_filter_event (dpyinfo, &event_copy))
> >             continue;
> >  #ifdef HAVE_XINPUT2
> >         }
> >
> > > To summarize: for feature/igc at 2025/02/10 with or without the patch,
> > > the issue happens but at a much lower probability (compared to
> > > scratch/igc at 2024/11/24)
> >
> > Did you ever see this message?
> >
> >         fprintf(stderr,
> >                 "%s,%d: The application disposed a key event with %ld serial.\n",
> >                 __FILE__, __LINE__,
> >                 im->private.proto.fabricated_serial);
> >
> > It should be printed on stderr when an out-of-order event arrives in
> > XFilterEvent.
>
> No, I didn't see this message.
>
> >
> > > I think I will try bisecting between the two versions and see what affects this.
> >
> > That sounds like a lot of work!  Sorry I couldn't come up with anything
> > but the patch above, and I understand if you don't want to try it, but
> > if you do, please let me know how it goes!
> >
> > And if you can find a better recipe for reproducing this, please let us
> > know, too.
> >
> > Thanks again for the report.
>
> No problem at all, I will let you know if I find anything. Thank you
> for your help.
>
> Yikai
diff --git a/src/xterm.c b/src/xterm.c
index c3137945ac5..41afa16ca99 100644
--- a/src/xterm.c
+++ b/src/xterm.c
@@ -626,11 +626,19 @@ Copyright (C) 1989, 1993-2025 Free Software Foundation, Inc.
 #include <stdlib.h>
 #include <math.h>
 #include <signal.h>
+#include <time.h>
 
 #include "lisp.h"
 #include "blockinput.h"
 #include "sysstdio.h"
 
+#define DEBUG_PRINTF(fmt, ...)						\
+  do {									\
+    struct timespec tp;							\
+    clock_gettime(CLOCK_MONOTONIC, &tp);				\
+    fprintf(stderr, "[line %d, %ld.%ld] " fmt, __LINE__, (long)tp.tv_sec, (long)tp.tv_nsec, ##__VA_ARGS__); \
+  } while(0)
+
 /* This may include sys/types.h, and that somehow loses
    if this is not done before the other system files.  */
 #include "xterm.h"
@@ -13040,7 +13048,10 @@ x_dnd_begin_drag_and_drop (struct frame *f, Time time, Atom xaction,
 		  != event_display->xi2_opcode))
 	    {
 #endif
-	      if (!x_filter_event (event_display, &next_event))
+             XEvent event_copy = next_event;
+             if (event_copy.type == KeyPress || event_copy.type == KeyRelease)
+               event_copy.xkey.time = CurrentTime;
+             if (!x_filter_event (event_display, &event_copy))
 		handle_one_xevent (event_display,
 				   &next_event, &finish, &hold_quit);
 #ifdef HAVE_XINPUT2
@@ -17892,8 +17903,12 @@ x_filter_event (struct x_display_info *dpyinfo, XEvent *event)
    XFilterEvent because that's the one for which the IC
    was created.  */
 
+  //usleep (10000);
   struct frame *f1;
 
+  if (event->type == KeyPress || event->type == KeyRelease)
+    if (event->xkey.time > 1)
+      emacs_abort();
 #if defined HAVE_XINPUT2 && defined USE_GTK
   bool xinput_event = false;
   if (dpyinfo->supports_xi2
@@ -17966,6 +17981,9 @@ event_handler_gdk (GdkXEvent *gxev, GdkEvent *ev, gpointer data)
   XEvent *xev = (XEvent *) gxev;
 
   block_input ();
+  DEBUG_PRINTF( "event_handler_gdk enter: type=%d, current_count=%d\n",
+		xev->type,
+		current_count);
   if (current_count >= 0)
     {
       struct x_display_info *dpyinfo;
@@ -17976,10 +17994,16 @@ event_handler_gdk (GdkXEvent *gxev, GdkEvent *ev, gpointer data)
       /* Filter events for the current X input method.
          GTK calls XFilterEvent but not for key press and release,
          so we do it here.  */
+      XEvent xev_copy;
+      xev_copy = *xev;
+      DEBUG_PRINTF( "event_handler_gdk: ignoring time %ld\n",
+		    (long) xev_copy.xkey.time);
+      xev_copy.xkey.time = CurrentTime;
       if ((xev->type == KeyPress || xev->type == KeyRelease)
 	  && dpyinfo
-	  && x_filter_event (dpyinfo, xev))
+         && x_filter_event (dpyinfo, &xev_copy))
 	{
+	  DEBUG_PRINTF("filtered!");
 	  unblock_input ();
 	  return GDK_FILTER_REMOVE;
 	}
@@ -24131,7 +24155,8 @@ handle_one_xevent (struct x_display_info *dpyinfo,
 		  copy.xkey.window = xev->event;
 		  copy.xkey.root = xev->root;
 		  copy.xkey.subwindow = xev->child;
-		  copy.xkey.time = xev->time;
+                 DEBUG_PRINTF( "case XI_KeyPress popup_activated: ignoring time %ld\n", (long) xev->time);
+                 copy.xkey.time = CurrentTime;
 		  copy.xkey.state = state;
 		  xi_convert_button_state (&xev->buttons, &copy.xkey.state);
 
@@ -24189,7 +24214,8 @@ handle_one_xevent (struct x_display_info *dpyinfo,
 	      xkey.window = xev->event;
 	      xkey.root = xev->root;
 	      xkey.subwindow = xev->child;
-	      xkey.time = xev->time;
+             DEBUG_PRINTF( "case XI_KeyPress: ignoring time %ld\n", (long) xev->time);
+             xkey.time = CurrentTime;
 	      xkey.state = state;
 	      xkey.x = lrint (xev->event_x);
 	      xkey.y = lrint (xev->event_y);
@@ -24631,7 +24657,8 @@ handle_one_xevent (struct x_display_info *dpyinfo,
 	      xkey.window = xev->event;
 	      xkey.root = xev->root;
 	      xkey.subwindow = xev->child;
-	      xkey.time = xev->time;
+             DEBUG_PRINTF( "case XI_KeyRelease: ignoring time %ld\n", (long) xev->time);
+             xkey.time = CurrentTime;
 	      xkey.state = xi_convert_event_keyboard_state (xev);
 	      xkey.x = lrint (xev->event_x);
 	      xkey.y = lrint (xev->event_y);
@@ -25765,7 +25792,14 @@ XTread_socket (struct terminal *terminal, struct input_event *hold_quit)
 	  /* Input extension key events are filtered inside
 	     handle_one_xevent.  */
 #endif
-	  if (x_filter_event (dpyinfo, &event))
+         XEvent event_copy = event;
+         if (event_copy.type == KeyPress || event_copy.type == KeyRelease)
+           {
+             DEBUG_PRINTF( "XTread_socket: ignoring time %ld\n", (long) event.xkey.time);
+             event_copy.xkey.time = CurrentTime;
+           }
+
+         if (x_filter_event (dpyinfo, &event_copy))
 	    continue;
 #ifdef HAVE_XINPUT2
 	}