Re: trunk r116499: Improve dbus error handling; detect bus failure

[Daniel Colascione <dancol@dancol.org>]

On 02/24/2014 05:14 AM, Michael Albinus wrote:
> Michael Albinus <michael.albinus@gmx.de> writes:
>
>> --8<---------------cut here---------------start------------->8---
>> Debugger entered--Lisp error: (dbus-error "call timed out")
>>    signal(dbus-error ("call timed out"))
>>    byte-code(...)
>>    dbus-list-names(:session)
>>    dbus-register-method(:session "a.b" "/a/b" "a.b" "c" ignore)
>>    eval((dbus-register-method :session "a.b" "/a/b" "a.b" "c" (quote ignore)) nil)
>>    eval-last-sexp-1(nil)
>>    eval-last-sexp(nil)
>>    call-interactively(eval-last-sexp nil nil)
>>    command-execute(eval-last-sexp)
>> --8<---------------cut here---------------end--------------->8---
>>
>> *Messages* contains the traces.
>
> PS: The *Messages* buffer shows, that the result for dbus-list-names(:session)
> has arrived. Maybe your new mechanism has kicked off the result from
> `dbus-return-values-table', or it could not be read due to the changed layout.

Thanks for coming up with that. I can only repro this problem with 
dbus-debug turned on, but I think this issue is what Peter's been 
hitting too. It's actually a core Emacs event loop bug that we never 
noticed before due to checking read-event's return value and breaking 
the loop early if it ever returns a dbus event.

The problem is this code from read_char in keyboard.c:

   if (NILP (c))
     {
       c = read_decoded_event_from_main_queue (end_time, local_getcjmp,
                                               prev_event, used_mouse_menu);
       if (end_time && timespec_cmp (*end_time, current_timespec ()) <= 0)
         goto exit;
       if (EQ (c, make_number (-2)))
         {
	  /* This is going to exit from read_char
	     so we had better get rid of this frame's stuff.  */
	  UNGCPRO;
           return c;
         }
   }

c here is our dbus event. We managed to successfully read the event, but 
by the time we returned from read_decoded_event_from_main_queue, we've 
exceeded the allowed timeout, so we jump directly to exit, completely 
bypassing the part of read_char that sends the event to 
special_event_map. As a result, we drop the event on the floor and never 
process it. The race is small, but because we're using very small 
timeout values, we hit it more than some other code might.

I apparently have a fast enough machine that I never hit this problem 
during testing. :-)

Can you try this patch?

=== modified file 'src/keyboard.c'
--- src/keyboard.c	2014-02-08 04:02:16 +0000
+++ src/keyboard.c	2014-02-24 13:47:18 +0000
@@ -2891,8 +2891,12 @@
      {
        c = read_decoded_event_from_main_queue (end_time, local_getcjmp,
                                                prev_event, 
used_mouse_menu);
-      if (end_time && timespec_cmp (*end_time, current_timespec ()) <= 0)
-        goto exit;
+      if (NILP(c) && end_time &&
+          timespec_cmp (*end_time, current_timespec ()) <= 0)
+        {
+          goto exit;
+        }
+
        if (EQ (c, make_number (-2)))
          {
  	  /* This is going to exit from read_char