bug#21313: 25.0.50; Strange errors from dbus-handle-event

[Tassilo Horn]

Eli Zaretskii <eliz@gnu.org> writes:

>> I added some debug code which spits out something like
>> 
>> record_char: 107
>>   -> NOT storing as part of macro
>>   -2> set to recent_keys at index 28
>> 
>> where the 107 is the result of formatting the Lisp_Object with "%S", the
>> second line indicates if store_kbd_macro_char is doing something, and
>> the -2> line means that the second ASET (recent_keys, ...) invocation in
>> record_char has been executed.
>> 
>> That's what you had in mind, right?
>
> Yes, thanks.

Ok, great.  But somehow my debugging code changes the behavior with
respect to hitting C-g in the minibuffer and I don't see how that can
happen.

Concretely, normally C-g in the minibuffer will exit the minibuffer or
exit the recursive minibuffer popping to the previous one.  But with my
change, I need to hit C-g twice in quick succession.  A single C-g does
nothing (record_char isn't called at all), and pressing it many times
with reasonably long pauses in between does nothing, too (no
record_char).

Oh, wait.  Now I can tell you exactly how quickly I have to type the
second C-g.  When I type C-g, the echo area shows Quit and then switches
back to the prompt I had before.  The second C-g must come within the
time the echo area still shows Quit.

That's the output I get when doing M-x C-g C-g quickly.  The second
record_char output appears just after the second C-g in the sequence.

--8<---------------cut here---------------start------------->8---
record_char: 134217848 ;; M-x
  -> NOT storing as part of macro
  -2> set to recent_keys at index 15
record_char: 7 ;; issued after C-g twice in quick succession
  -> NOT storing as part of macro
  -2> set to recent_keys at index 17
--8<---------------cut here---------------end--------------->8---

And these are my changes.  Do you see anything stupid in there, or is
this some sort of a timing issue (which would at least partially explain
why I seem to be the only one seeing these "strange problems")?

--8<---------------cut here---------------start------------->8---
debug-record_char 74795245e4afc71dac56cd625a574a13be42227e
Author:       Tassilo Horn <tsdh@gnu.org>
AuthorDate:   Wed Oct 14 21:22:27 2015 +0200
Commit:       Tassilo Horn <tsdh@gnu.org>
CommitDate:   Thu Oct 15 13:29:28 2015 +0200

Parent:     59def59 Refer to `(elisp)Basic Completion' in completing-read 
docstring
Merged:     debug-record_char master
Containing: debug-record_char
Follows:    emacs-24.5-rc3-fixed (6228)

Debug record_char

2 files changed, 11 insertions(+), 1 deletion(-)
src/keyboard.c | 8 ++++++++
src/macros.c   | 4 +++-

modified   src/keyboard.c
@@ -3151,6 +3151,9 @@ help_char_p (Lisp_Object c)
 static void
 record_char (Lisp_Object c)
 {
+  AUTO_STRING (format, "%S");
+  printf ("record_char: %s\n", SSDATA (CALLN (Fformat, format, c)));
+
   int recorded = 0;
 
   if (CONSP (c) && (EQ (XCAR (c), Qhelp_echo) || EQ (XCAR (c), 
Qmouse_movement)))
@@ -3213,6 +3216,7 @@ record_char (Lisp_Object c)
            {
              ASET (recent_keys, ix1, c);
              recorded = 1;
+             printf ("  -1> set to recent_keys at index %d\n", ix1);
            }
        }
     }
@@ -3223,6 +3227,7 @@ record_char (Lisp_Object c)
     {
       total_keys += total_keys < NUM_RECENT_KEYS;
       ASET (recent_keys, recent_keys_index, c);
+      printf ("  -2> set to recent_keys at index %d\n", recent_keys_index);
       if (++recent_keys_index >= NUM_RECENT_KEYS)
        recent_keys_index = 0;
     }
@@ -3242,9 +3247,12 @@ record_char (Lisp_Object c)
          if (--recent_keys_index < 0)
            recent_keys_index = NUM_RECENT_KEYS - 1;
          ASET (recent_keys, recent_keys_index, Qnil);
+         printf ("  -3> set to recent_keys at index %d\n", recent_keys_index);
        }
     }
 
+  fflush (stdout);
+
   num_nonmacro_input_events++;
 
   /* Write c to the dribble file.  If c is a lispy event, write
modified   src/macros.c
@@ -185,6 +185,7 @@ store_kbd_macro_char (Lisp_Object c)
 
   if (!NILP (KVAR (kb, defining_kbd_macro)))
     {
+      printf ("  -> storing as part of macro\n");
       if (kb->kbd_macro_ptr - kb->kbd_macro_buffer == kb->kbd_macro_bufsize)
        {
          ptrdiff_t ptr_offset, end_offset, nbytes;
@@ -200,9 +201,10 @@ store_kbd_macro_char (Lisp_Object c)
          kb->kbd_macro_ptr = kb->kbd_macro_buffer + ptr_offset;
          kb->kbd_macro_end = kb->kbd_macro_buffer + end_offset;
        }
-
       *kb->kbd_macro_ptr++ = c;
     }
+  else
+    printf ("  -> NOT storing as part of macro\n");
 }
 
 /* Declare that all chars stored so far in the kbd macro being defined
--8<---------------cut here---------------end--------------->8---

Bye,
Tassilo