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

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

[Michael Albinus]

Daniel Colascione <dan.colascione@gmail.com> writes:

> +	(dbus-handle-bus-disconnect): New function.  React to bus
> +	disconnection signal by synthesizing dbus error for each
> +	pending synchronous or asynchronous call.

This is a new functionality. Why do you want to add it during feature
freeze? And what is the reasoning behind? When a D-Bus bus disconnects,
there might be more serious problems but pending method calls.

Is it about performance, and abortion of such pending calls? When does
it happen, that a bus disconnect for you?

> +	(dbus-notice-synchronous-call-errors): New function.
> +	(dbus-handle-event): Raise errors directly only when `dbus-debug'
> +	is true, not all the time.

Why that? You cannot assume that `dbus-event-error-functions' is non-nil
(and contains `dbus-notice-synchronous-call-errors').

I still don't see what you are trying to resolve. Lisp errors are shown
when happening in handlers, what else do you want to achieve? As usual a
typical use case would help.

And *if* you are applying such changes, I would expect respective doc
changes, for example explainig the (changed) structure of the values in
`dbus-return-values-table', or mentioning
`dbus-notice-synchronous-call-errors' and its intended use in dbus.texi.

In short, I'm not against such changes if the intention is
understood. But I believe it is a bad timing to apply them during
feature freeze, and w/o discussing them in emacs-devel.

Best regards, Michael.

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

[Daniel Colascione]

This change is a bug fix --- a non-trivial bug fix, but a bug fix. 
There's no contractual behavior change.

On 02/24/2014 12:18 AM, Michael Albinus wrote:
> Daniel Colascione <dan.colascione@gmail.com> writes:
>
>> +	(dbus-handle-bus-disconnect): New function.  React to bus
>> +	disconnection signal by synthesizing dbus error for each
>> +	pending synchronous or asynchronous call.
>
> This is a new functionality. Why do you want to add it during feature
> freeze? And what is the reasoning behind? When a D-Bus bus disconnects,
> there might be more serious problems but pending method calls.

And you would propose to just ignore bus disconnects? Sending an error 
is the best we can do.

> Is it about performance, and abortion of such pending calls? When does
> it happen, that a bus disconnect for you?

It's not about performance, but since I had to restructure the code to 
handle errors anyway, I used a mechanism that doesn't involve so many 
hash table lookups.

>
>> +	(dbus-notice-synchronous-call-errors): New function.
>> +	(dbus-handle-event): Raise errors directly only when `dbus-debug'
>> +	is true, not all the time.
>
> Why that? You cannot assume that `dbus-event-error-functions' is non-nil
> (and contains `dbus-notice-synchronous-call-errors').

We still call dbus-event-error-functions.  In fact, that's how error 
propagation to synchronous calls works now.

> I still don't see what you are trying to resolve. Lisp errors are shown
> when happening in handlers, what else do you want to achieve? As usual a
> typical use case would help.

First of all, before my change, the dbus could would just hang in 
response to bus disconnects. Now calls terminate immediately with a 
reasonable error. dbus disconnects the bus on certain usage errors. Here 
is a call that results in an immediate bus disconnect:

(dbus-call-method :session "org.freedesktop.secrets" 
"/org/freedesktop/secrets/collection/login" 
"org.freedesktop.Secret.Collection" "SearchItems" '(:array (:dict-entry 
"host" ("xxxx" "xxxx")) (:dict-entry "port" "imaps")))

Additionally, I strongly dislike signaling errors from the read-event 
handler: doing that makes it easy to "leak" errors up to unrelated outer 
dbus calls. Please carefully consider cases where more than one dbus 
call might be pending on the stack at a time.

> And *if* you are applying such changes, I would expect respective doc
> changes, for example explainig the (changed) structure of the values in
> `dbus-return-values-table', or mentioning
> `dbus-notice-synchronous-call-errors' and its intended use in dbus.texi.

Neither of these symbols is public. The contractual behavior has not 
changed.

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

[Michael Albinus]

Daniel Colascione <dancol@dancol.org> writes:

>>> +	(dbus-notice-synchronous-call-errors): New function.
>>> +	(dbus-handle-event): Raise errors directly only when `dbus-debug'
>>> +	is true, not all the time.
>>
>> Why that? You cannot assume that `dbus-event-error-functions' is non-nil
>> (and contains `dbus-notice-synchronous-call-errors').
>
> We still call dbus-event-error-functions.  In fact, that's how error
> propagation to synchronous calls works now.

Yes, but you also silently assume that `dbus-notice-synchronous-call-errors'
is called from there ...

> First of all, before my change, the dbus could would just hang in
> response to bus disconnects. Now calls terminate immediately with a
> reasonable error. dbus disconnects the bus on certain usage
> errors. Here is a call that results in an immediate bus disconnect:
>
> (dbus-call-method :session "org.freedesktop.secrets"
> "/org/freedesktop/secrets/collection/login"
> "org.freedesktop.Secret.Collection" "SearchItems" '(:array
> (:dict-entry "host" ("xxxx" "xxxx")) (:dict-entry "port" "imaps")))

Wow, this is really strange. It's not obvious to me whether this is a
D-Bus bug, or whether this is intended by the "org.freedesktop.secrets"
daemon. Anyway, you are right, this must be catched.

>> And *if* you are applying such changes, I would expect respective doc
>> changes, for example explainig the (changed) structure of the values in
>> `dbus-return-values-table', or mentioning
>> `dbus-notice-synchronous-call-errors' and its intended use in dbus.texi.
>
> Neither of these symbols is public. The contractual behavior has not
> changed.

You have added `dbus-notice-synchronous-call-errors' to
`dbus-event-error-functions'. This is a public change, and it deserves
documentation.

Furthermore, I had developers in mind when I've asked for doc
enhancement. Even I, as the original writer of the code, need to consult
the doc strings for hash table structures and alike. It would ease our
life, if the doc is up-to-date and reasonable.

Best regards, Michael.

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

[Peter Münster]

Hi,

Perhaps related to the latest dbus-changes:

With latest emacs-trunk (r116544), emacs hangs often for about 20s after
calling `notifications-notify'. After the hang, this message appears:
`dbus-error: "call timed out"'

No problem with r116286.

-- 
           Peter

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

[Daniel Colascione]

On 02/24/2014 03:45 AM, Peter Münster wrote:
> Perhaps related to the latest dbus-changes:
>
> With latest emacs-trunk (r116544), emacs hangs often for about 20s after
> calling `notifications-notify'. After the hang, this message appears:
> `dbus-error: "call timed out"'
>
> No problem with r116286.

It works for me. Do you have a repro?

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

[Daniel Colascione]

On 02/24/2014 04:50 AM, Daniel Colascione wrote:
> On 02/24/2014 03:45 AM, Peter Münster wrote:
>> Perhaps related to the latest dbus-changes:
>>
>> With latest emacs-trunk (r116544), emacs hangs often for about 20s after
>> calling `notifications-notify'. After the hang, this message appears:
>> `dbus-error: "call timed out"'
>>
>> No problem with r116286.
>
> It works for me. Do you have a repro?

Also, just a hunch: is dbus-event-error-functions empty? I think Michael 
is right about needing to handle error notifications
explicitly instead of going through the hook.

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

[Michael Albinus]

Daniel Colascione <dancol@dancol.org> writes:

> On 02/24/2014 03:45 AM, Peter Münster wrote:
>> Perhaps related to the latest dbus-changes:
>>
>> With latest emacs-trunk (r116544), emacs hangs often for about 20s after
>> calling `notifications-notify'. After the hang, this message appears:
>> `dbus-error: "call timed out"'
>>
>> No problem with r116286.
>
> It works for me. Do you have a repro?

I could reproduce it occasionally, not 100%. Run "emacs -Q". Eval:

(require 'dbus)
(setq dbus-debug t)
(dbus-register-method :session "a.b" "/a/b" "a.b" "c" 'ignore)

It times out after 25". The backtrace is

--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.

Best regards, Michael.

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

[Michael Albinus]

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.

Best regards, Michael.

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

[Daniel Colascione]

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

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

[Michael Albinus]

Daniel Colascione <dancol@dancol.org> writes:

> 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.

Well, your shortened timeout in the loop has provoked this error at
least. That's worth the trouble :-)

> Can you try this patch?

Works for me. On one of my slower machines, I've run "emacs -Q" at least
10 times; the error didn't happen again.

So please install the patch.

Best regards, Michael.

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

[Peter Münster]

On Mon, Feb 24 2014, Michael Albinus wrote:

>> Can you try this patch?
>
> Works for me.

For me too. Thanks!

-- 
           Peter