Unexpected reply

[mfiano]

This started happening a few months ago, and I'm just getting around to reporting it because it is quite annoying. Every few minutes, this error is invoked, which pauses Emacs for a good 5 seconds while I am typing.

error in process filter: sly-dispatch-event: Unexpected reply: 1778 (:ok ("(define-hook ===> hook-type <=== (self component-type &key (optimize t)) &body body)" t))
error in process filter: Unexpected reply: 1778 (:ok ("(define-hook ===> hook-type <=== (self component-type &key (optimize t)) &body body)" t))

Here's another occurence in my Messages buffer:

-event: Unexpected reply: 904 (:ok ("(defun name ===> lambda-list <=== &body body)" t))
error in process filter: Unexpected reply: 904 (:ok ("(defun name ===> lambda-list <=== &body body)" t))

and another:

error in process filter: sly-dispatch-event: Unexpected reply: 606 (:ok (:not-available t))
error in process filter: Unexpected reply: 606 (:ok (:not-available t))

and another:

error in process filter: sly-dispatch-event: Unexpected reply: 165 (:ok (:not-available t))
error in process filter: Unexpected reply: 165 (:ok (:not-available t))

and one more from today:

error in process filter: sly-dispatch-event: Unexpected reply: 2999 (:ok (:not-available t))
error in process filter: Unexpected reply: 2999 (:ok (:not-available t))

[joaotavora]

Yuck, this isn't good. I see this once in a while , too, but not nearly "every few minutes". I see it once a week at most. It's very hard to pin down. You can give me some help tho:

1. Tell me how often you see this. Is it really every few minutes? That's very odd, but in a sense good.
2. Since it's so easy to reproduce for you, Git bisecting to an offending prior commit would be extremely useful.

João

[mfiano]

@joaotavora I would say every 20 minutes to an hour, so not that easy to bisect. Is there anything else I can do to help pin it down?

[joaotavora]

In principle, with the Elisp evaluation model I know, this shouldn't matter, but you can try with this patch:

diff --git a/sly.el b/sly.el
index ae88a8ed..ca58bf24 100644
--- a/sly.el
+++ b/sly.el
@@ -2541,8 +2541,8 @@ Debugged requests are ignored."
            (when (and (sly-use-sigint-for-interrupt) (sly-busy-p))
              (sly-display-oneliner "; pipelined request... %S" form))
            (let ((id (cl-incf (sly-continuation-counter))))
-             (sly-send `(:emacs-rex ,form ,package ,thread ,id ,@extra-options))
              (push (cons id continuation) (sly-rex-continuations))
+             (sly-send `(:emacs-rex ,form ,package ,thread ,id ,@extra-options))
              (sly--refresh-mode-line)))
           ((:return value id)
            (let ((rec (assq id (sly-rex-continuations))))

[joaotavora]

The code path that I'm thinking about should be equivalent to SLIME's, so I find this very strange. Maybe you upgraded Emacs versions a month ago or something like that?

[mfiano]

I am on Arch Linux, so get frequent updates, yes. Currently on Emacs 27.1

[joaotavora]

I am on Arch Linux, so get frequent updates, yes. Currently on Emacs 27.1

That's fairly recent, and what I use as well (actually I use master). Maybe you can downgrade momentarily to 26.3 or keep it besides Emacs 27.

Anyway, this seems to be Eldoc/Autodoc exclusive, so shooshing those errors in those circunstances could be an option. But I'd like to get to the bottom of it. Please try my patch for a while.

[mfiano]

Actually, come to think of it, this started happening when I upgraded from 27 to 27.1 back when it was released in August, but I also updated all my Emacs packages at the same time, so...

[joaotavora]

From 27 to 27.1? That's odd. Were you using a pretest? Or did you mean 26?

[mfiano]

Let me consult my Linux package update log...

[2020-02-21T00:39:27+0000] [ALPM] installed emacs (26.3-1)
[2020-05-22T22:03:46-0400] [ALPM] upgraded emacs (26.3-1 -> 26.3-2)
[2020-08-13T17:39:33-0400] [ALPM] upgraded emacs (26.3-2 -> 27.1-2)

Ah, sorry. So it happened with 26.3 -> 27.1.

[joaotavora]

Nice linux distro btw. Someday I'll switch myself, what "flavor" of Arch, if any, are you on?

[mfiano]

Plain old Arch Linux.

[joaotavora]

Anyway, so as you can see by my patch, my suspicion/working hypothesis is that 27.1 somehow allowed (contrary to 26.3) sly-send or its calles to receive output from subprocesses "prematurely". Basically Eldoc/Autodoc would have responded so damn quickly that there wouldn't have been enough time to run the next statement so when they reply back the "continuation" isn't there and you get that error. So the solution would be to first register the continuation, and then send sly-send.

EDIT: this working hypothesis is now known invalid. The real reason is that process-send-string is sometimes silently exiting non-locally when called from a timer.

[mfiano]

Sure, I am upgrading my packages right now, then I will try your patch, and perhaps Emacs HEAD. Thanks

[joaotavora]

Actually, I wouldn't do that. I would try one thing at a time.

[joaotavora]

Starting with the patch, maybe.

[mfiano]

Yes, I know. I have some other outstanding Emacs issues to take care of too, so first I'm updating packages and inspecting all that. I have a backup on my NAS of the previous state in case things go awful, and to try your patch in isolation.

[mfiano]

@joaotavora With your patch, eldoc no longer gives any hints at all.

[mfiano]

In looking over my Emacs config though I have (setq eldoc-idle-delay 0.1) which differs from the default of 0.5 because I wanted it more responsive. This leads me to believe there could be some kind of race condition. I will change it to the default in the meantime and see if that helps reduce the chance, even if that is an ugly hack.

[joaotavora]

@joaotavora With your patch, eldoc no longer gives any hints at all.

Wow, that is something. I've pushed a branch with the patch. Please point your copy of SLY to it, make sure you don't have any stale .elc files, and try to reproduce the problem with a bare Emacs.

[joaotavora]

and try to reproduce the problem with a bare Emacs.

By problem I mean any of the two problems, the error or the missing ElDoc. By bare Emacs I mean Emacs -Q.

[mfiano]

eldoc seems to be working, even though nothing appears to be different from that patch and what i changed. And I always delete elc files between each run in these types of cases. Will keep an eye out for the error now

[mfiano]

I spoke too soon. eldoc stopped printing out signatures in the minibuffer.

[joaotavora]

Michael Fiano <notifications@github.com> writes:

I spoke too soon. eldoc stopped printing out signatures in the minibuffer.

I reproduced this and am looking at it, it's the converse of the error you got earlier. You can likely get out of this "no-ElDoc" state with `M-x sly-forget-pending-events`. If you have the standard SLY mode-line you should have spotted a continuation counter stuck at "1" when ElDoc stopped working. João

[joaotavora]

Michael Fiano <notifications@github.com> writes:

I spoke too soon. eldoc stopped printing out signatures in the minibuffer.

I've pushed another commit to the branch that I'd with you'd try out. For the record this is related to some mysterious non-local exits when process-send-string is called from within a timer. This is likely an Emacs bug. It also connects to another strange behaviour I observed recently. Anyway, try out the patch and let me know. Cheers.

[joaotavora]

I've pinned this down to a likely Emacs bug. Here is the report I made: https://debbugs.gnu.org/cgi/bugreport.cgi?bug=45117

@mfiano The most recent commit will probably be the end of it regardless of whether the problem is fixed in Emacs or not, but I'd still appreciate that you'd test it.

[mfiano]

Interesting. Nice debugging there! I will be using your latest commit and let you know how it goes.

P.S. South Bank Common Lisp is not a thing :)

[joaotavora]

P.S. South Bank Common Lisp is not a thing :)

Nah-ah!!!, it's a thing I got here that noone knows and only I use!

🤦 🤦

[mfiano]

Unfortunately, your latest changes didn't solve the issue:

error in process filter: sly-dispatch-event: Unexpected reply: 192 (:ok ("(let bindings &body ===> body <===)" t))
error in process filter: Unexpected reply: 192 (:ok ("(let bindings &body ===> body <===)" t))

error in process filter: sly-dispatch-event: Unexpected reply: 274 (:ok ("(defun name lambda-list &body ===> body <===)" t))
error in process filter: Unexpected reply: 274 (:ok ("(defun name lambda-list &body ===> body <===)" t))

[joaotavora]

Likely you didn't compile them, or have a stale elc.. I'll look later but you can substitute the latest by the if version that prints something everytime it catches the bug. Try that.

[mfiano]

I made sure to remove all packages, not just ELC, but everything, and did a checkout of that specific branch for Sly.

[joaotavora]

I still think you missed something. I'll push a version with a little bit more debugging info and then we can check Messages to be sure.

[joaotavora]

Thinking x2 about it, there is indeed a possibility of unexpected reply, I just never got it (and I got a lot of observations of the bug). but lets run this version so we get more feedback.

[joaotavora]

By the way, you don't have to completely purge everything to get this, just go to the sly.el file and re-evaluate that definition

[mfiano]

Give me a few minutes to finish up and I will try. I will say though, that the previous patch seemed to result in the error far less often, or it could just be the computer gods laughing at me. In any case, I will run with the latest for a while and report what I see.

[mfiano]

After a few minutes, this is in *Messages*

[sly] Connecting to Slynk on port 41235..
[sly] Connected. Hack and be merry!
[sly] [issue#385] likely `process-send-string' exited non-locally from timer.
[sly] [issue#385] likely `process-send-string' exited non-locally from timer. [2 times]

[joaotavora]

And also some "unexpecteds?"

[mfiano]

Negative

[joaotavora]

let's wait though, I think eventually you'll bump into one.

[mfiano]

I copied some code I already wrote, typing as fast as I could, as that seems to generate them quickly:

[sly] Connecting to Slynk on port 41235..
[sly] Connected. Hack and be merry!
[sly] [issue#385] likely `process-send-string' exited non-locally from timer.
No completion found
[sly] [issue#385] likely `process-send-string' exited non-locally from timer. [10 times]
next-line: End of buffer
[sly] [issue#385] likely `process-send-string' exited non-locally from timer. [5 times]
Beginning of buffer [2 times]

[joaotavora]

yeah, with a short eldoc-idle-delay it seems to happen very often. No "unexpecteds" though, right?

[mfiano]

No unexpecteds with the latest patch.

[joaotavora]

(the latest patch is the same as the one before, btw :-) just more debugging info)

[joaotavora]

Anyway, keep testing, I think you'll reach an unexpected or two, by my calculations, it's certainly possible, and likely that was happening before. It would also explain the perceived decrease in frequency you mentioned.

[joaotavora]

When you confirm this, I'll have a patch to fix those

[mfiano]

Sure I will keep testing. Just to be clear:

• When the "unexpected"s were frequent, every time they popped up, Emacs would freeze for about 5 seconds.

• When they pop up rarely, they still freeze Emacs for about 5 seconds, but the frequent debug message that is emitted now does not freeze Emacs.

[joaotavora]

By the way. It's great that you use SLY so intensively and take the time to report these bugs and help me debug them. Very appreciated 👌

[mfiano]

So, it's much more bearable now at least. Oh no problem at all. Thank you for being such a great maintainer, because I know you're a very busy person.

[joaotavora]

When they pop up rarely, they still freeze Emacs for about 5 seconds, but the frequent debug message that is emitted now does not freeze Emacs.

Right, the debug message is just a tracer. You can comment it out.

[mfiano]

Yep:

error in process filter: sly-dispatch-event: Unexpected reply: 1986 (:ok ("(define-compiler-macro make-component (type &rest ===> args <===) &body body)" t))
error in process filter: Unexpected reply: 1986 (:ok ("(define-compiler-macro make-component (type &rest ===> args <===) &body body)" t))

[joaotavora]

After some very intensive investigation, I came to the correct fix. I shall be ⚡ if this doesn't fix it. Problem was in Emacs, but in Elisp and not in C, thankfully.

https://debbugs.gnu.org/cgi/bugreport.cgi?bug=45117

[mfiano]

Excellent. Thank you for all your work!