clojure-emacs / cider

The Clojure Interactive Development Environment that Rocks for Emacs
https://cider.mx
GNU General Public License v3.0
3.52k stars 643 forks source link

Wrong type argument: plistp #3630

Closed r0man closed 4 months ago

r0man commented 4 months ago

Expected behavior

CIDER not crashing on eldoc requests

Actual behavior

Since a couple of weeks I have this strange behaviour that CIDER randomly starts crashing on eldoc requests. When this happens I see messages like the following flooding CIDER and rendering it unusable. My problem is that I can't reliably reproduce it. It probably has something to do with my Emacs config. It does not happen with a clean Emacs with only CIDER loaded.

I'm having a hard time tracking this down. I haven't figured out a reliably way to reproduce it. I starts happening after some time, and then continuously.

The error I'm getting look like this:

error in process filter: nrepl-log-message: Wrong type argument: plistp, ("2024-03-08 13:51:56.575869187" "time-stamp" "macro" "type" ("done") "status" "2e871f64-ce2d-472e-99d0-2e0ae0991aa8" "session" "clojure.test" "ns" "testing" "name" "14" "id" (("string" "&" "body")) "eldoc" "Adds a new string ..." "docstring" "clojure.core" "docstring" "Equality. Returns ..." "eldoc" (("x") ("x" "y") ("x" "y" "&" "more")) "id" "15" "name" "=" "ns" "clojure.core" "session" "2e871f64-ce2d-472e-99d0-2e0ae0991aa8" "status" ("done") "type" "function")

The given list looks a bit suspicious to me. This is the pretty printed version of it:

("2024-03-08 13:51:56.575869187" "time-stamp"
 "macro" "type"
 ("done") "status"
 "2e871f64-ce2d-472e-99d0-2e0ae0991aa8" "session"
 "clojure.test" "ns"
 "testing" "name"
 "14" "id"
 (("string" "&" "body")) "eldoc"
 "Adds a new string ..." "docstring"

 "clojure.core"

 "docstring" "Equality. Returns ..."
 "eldoc" (("x") ("x" "y") ("x" "y" "&" "more"))
 "id" "15"
 "name" "="
 "ns" "clojure.core"
 "session" "2e871f64-ce2d-472e-99d0-2e0ae0991aa8"
 "status" ("done")
 "type" "function")

I think the list has the following issues:

Here is a stacktrace of a situation when it happens:

Debugger entered--Lisp error: (wrong-type-argument plistp ("macro" "type" ("done") "status" "692a66d1-b6d0-459a-b035-79246e17b482" "session" "clojure.core" "ns" "defn-" "name" "17" "id" (("name" "&" "decls")) "eldoc" "same as defn, yielding non-public def" "docstring" "example.core" "docstring" "Same as (def name (fn [params* ] exprs*)) or (def\n..." "eldoc" (("name" "doc-string?" "attr-map?" "[params*]" "prepost-map?" "body") ("name" "doc-string?" "attr-map?" "([params*] prepost-map? body)" "+" "attr-map?")) "id" "19" "name" "defn" "ns" "clojure.core" "session" "692a66d1-b6d0-459a-b035-79246e17b482" "status" ("done") "type" "macro"))
  lax-plist-put(("macro" "type" ("done") "status" "692a66d1-b6d0-459a-b035-79246e17b482" "session" "clojure.core" "ns" "defn-" "name" "17" "id" (("name" "&" "decls")) "eldoc" "same as defn, yielding non-public def" "docstring" "example.core" "docstring" "Same as (def name (fn [params* ] exprs*)) or (def\n..." "eldoc" (("name" "doc-string?" "attr-map?" "[params*]" "prepost-map?" "body") ("name" "doc-string?" "attr-map?" "([params*] prepost-map? body)" "+" "attr-map?")) "id" "19" "name" "defn" "ns" "clojure.core" "session" "692a66d1-b6d0-459a-b035-79246e17b482" "status" ("done") "type" "macro") "time-stamp" "2024-03-08 14:24:16.645061447")
  nrepl-log-message((dict "macro" "type" ("done") "status" "692a66d1-b6d0-459a-b035-79246e17b482" "session" "clojure.core" "ns" "defn-" "name" "17" "id" (("name" "&" "decls")) "eldoc" "same as defn, yielding non-public def" "docstring" "example.core" "docstring" "Same as (def name (fn [params* ] exprs*)) or (def\n..." "eldoc" (("name" "doc-string?" "attr-map?" "[params*]" "prepost-map?" "body") ("name" "doc-string?" "attr-map?" "([params*] prepost-map? body)" "+" "attr-map?")) "id" "19" "name" "defn" "ns" "clojure.core" "session" "692a66d1-b6d0-459a-b035-79246e17b482" "status" ("done") "type" "macro") response)
  nrepl--dispatch-response((dict "macro" "type" ("done") "status" "692a66d1-b6d0-459a-b035-79246e17b482" "session" "clojure.core" "ns" "defn-" "name" "17" "id" (("name" "&" "decls")) "eldoc" "same as defn, yielding non-public def" "docstring" "example.core" "docstring" "Same as (def name (fn [params* ] exprs*)) or (def\n..." "eldoc" (("name" "doc-string?" "attr-map?" "[params*]" "prepost-map?" "body") ("name" "doc-string?" "attr-map?" "([params*] prepost-map? body)" "+" "attr-map?")) "id" "19" "name" "defn" "ns" "clojure.core" "session" "692a66d1-b6d0-459a-b035-79246e17b482" "status" ("done") "type" "macro"))
  nrepl-client-filter(#<process nrepl-connection<1>> "d9:docstring261:Same as (def name (fn [params* ] e...")
  nrepl-send-sync-request(("op" "eldoc" "ns" #("integration.integration.specification-test" 0 42 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil help-echo cider--help-echo fontified t)) "sym" "defn" "context" "(__prefix__ initial-state [system]\n  {:system syst...") #<buffer *cider-repl example:localhost:34193(clj)*> abort-on-input)
  cider-nrepl-send-sync-request(("op" "eldoc" "ns" #("integration.integration.specification-test" 0 42 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil help-echo cider--help-echo fontified t)) "sym" "defn" "context" "(__prefix__ initial-state [system]\n  {:system syst...") #<buffer *cider-repl example:localhost:34193(clj)*> abort-on-input)
  cider-sync-request:eldoc("defn" nil nil "(__prefix__ initial-state [system]\n  {:system syst...")
  cider-eldoc-info("defn")
  cider-eldoc-info-at-point()
  cider-eldoc-info-in-current-sexp()

Any ideas how this can happen? Does this ring a bell to anyone?

Steps to reproduce the problem

Environment & Version information

CIDER version information

CIDER 1.13.1 (Santiago), nREPL 1.0.0 Clojure 1.11.1, Java 17.0.10

Lein / Clojure CLI version

Leiningen 2.10.0 on Java 17.0.10 OpenJDK 64-Bit Server VM

Emacs version

GNU Emacs 29.2 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.37, cairo version 1.16.0)

Operating system

Ubuntu 22.04.3 LTS

JDK distribution

openjdk version "17.0.10" 2024-01-16 OpenJDK Runtime Environment (build 17.0.10+7-Ubuntu-122.04.1) OpenJDK 64-Bit Server VM (build 17.0.10+7-Ubuntu-122.04.1, mixed mode, sharing)

vemv commented 4 months ago

Thanks!

Unfortunately it doesn't ring a bell to me.

I'd suggest that you (setq nrepl-log-messages t) on Emacs startup. Then please attach the entire *nrepl-log-<project>* here.

r0man commented 4 months ago

Hi @vemv ,

thanks for helping me with this. This is the NREPL log:

(-->
  id         "1"
  op         "clone"
  time-stamp "2024-03-08 14:38:53.103537506"
)
(<--
  id          "1"
  session     "1b96b096-310d-4acd-84e6-88dcbb160d31"
  time-stamp  "2024-03-08 14:38:53.113397000"
  new-session "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  status      ("done")
)
(-->
  id         "2"
  op         "clone"
  time-stamp "2024-03-08 14:38:53.124273481"
)
(<--
  id          "2"
  session     "f4b615ce-0f65-4d0c-bd77-4674a238cb39"
  time-stamp  "2024-03-08 14:38:53.125731492"
  new-session "e34d1403-1c76-494c-8ed5-55681cbde834"
  status      ("done")
)
(-->
  id         "3"
  op         "describe"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:53.144801602"
)
(<--
  id         "3"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:53.150220246"
  aux        (dict ...)
  ops        (dict ...)
  status     ("done")
  versions   (dict ...)
)
(-->
  id                                 "4"
  op                                 "eval"
  session                            "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp                         "2024-03-08 14:38:53.166719180"
  code                               "(when-let [requires (resolve 'clojure.main/repl-requires)]
 ..."
  column                             1
  file                               "*cider-repl nu/bloqueto:localhost:33963(clj)*"
  inhibit-cider-middleware           "true"
  line                               43
  nrepl.middleware.print/buffer-size 4096
  nrepl.middleware.print/options     (dict ...)
  nrepl.middleware.print/print       "cider.nrepl.pprint/pprint"
  nrepl.middleware.print/quota       1048576
  nrepl.middleware.print/stream?     "1"
)
(<--
  id         "4"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:53.188014626"
  value      "nil"
)
(<--
  id         "4"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:53.233525361"
  ns         "user"
)
(<--
  id         "4"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:53.233659205"
  status     ("done")
)
(-->
  id         "5"
  op         "out-subscribe"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:53.233917842"
)
(-->
  id                                 "6"
  op                                 "init-debugger"
  session                            "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp                         "2024-03-08 14:38:53.234131233"
  nrepl.middleware.print/buffer-size 4096
  nrepl.middleware.print/options     (dict ...)
  nrepl.middleware.print/print       "cider.nrepl.pprint/pprint"
  nrepl.middleware.print/quota       1048576
  nrepl.middleware.print/stream?     "1"
)
(-->
  id                           "7"
  op                           "version"
  session                      "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp                   "2024-03-08 14:38:53.236238036"
  debug                        "true"
  insert-newline-after-require "false"
  prefix-rewriting             "false"
)
(<--
  id         "7"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:53.279711767"
  status     ("done")
  version    "3.9.1"
)
(-->
  id                           "8"
  op                           "version"
  session                      "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp                   "2024-03-08 14:38:53.297298030"
  debug                        "true"
  insert-newline-after-require "false"
  prefix-rewriting             "false"
)
(<--
  id            "5"
  session       "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp    "2024-03-08 14:38:53.297542638"
  out-subscribe "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  status        ("done")
)
(<--
  id         "8"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:53.341494911"
  status     ("done")
  version    "3.9.1"
)
(-->
  id                           "9"
  op                           "artifact-list"
  session                      "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp                   "2024-03-08 14:38:53.358651560"
  debug                        "true"
  force                        "false"
  insert-newline-after-require "false"
  prefix-rewriting             "false"
)
(-->
  id                           "10"
  op                           "warm-ast-cache"
  session                      "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp                   "2024-03-08 14:38:53.358956326"
  debug                        "true"
  ignore-paths                 nil
  insert-newline-after-require "false"
  prefix-rewriting             "false"
)
(<--
  id         "9"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:53.799982042"
  artifacts  ("side-fx" ...)
  status     ("done")
)
(-->
  id         "11"
  op         "classpath"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:56.013256251"
)
(<--
  id         "11"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:56.029102431"
  classpath  ("/home/roman/workspace/nu/bloqueto/test/unit" ...)
  status     ("done")
)
(-->
  id              "12"
  op              "ns-list"
  session         "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp      "2024-03-08 14:38:56.048867827"
  exclude-regexps ("^cider.nrepl" "^refactor-nrepl" "^nrepl")
)
(<--
  id         "12"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:38:56.094389268"
  ns-list    ("arrangement.core" ...)
  status     ("done")
)
(<--
  id         "4"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:00.875380046"
  err        "WARNING: parse-double already refers to: #'clojure.core/pars..."
)
(-->
  id                             "13"
  op                             "eval"
  session                        "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp                     "2024-03-08 14:39:09.104172508"
  code                           "(ns integration.integration.specification-test
  (:require [..."
  column                         1
  file                           "/home/roman/workspace/nu/bloqueto/test/integration/integrati..."
  line                           1
  nrepl.middleware.print/print   "cider.nrepl.pprint/pr"
  nrepl.middleware.print/quota   1048576
  nrepl.middleware.print/stream? nil
  ns                             "user"
)
(-->
  id         "14"
  op         "eldoc"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:13.796126351"
  context    "(defn- __prefix__ []
  (atom (components/create-and-start-sy..."
  ns         #("integration.integration.specification-test" 0 42 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil help-echo cider--help-echo fontified t))
  sym        "setup"
)
(<--
  id         "14"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:14.057776481"
  status     ("done" "no-eldoc")
)
(-->
  id         "15"
  op         "eldoc"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:14.073451813"
  context    "(__prefix__ setup []
  (atom (components/create-and-start-sy..."
  ns         #("integration.integration.specification-test" 0 42 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil help-echo cider--help-echo fontified t))
  sym        "defn-"
)
(<--
  id         "15"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:14.161868780"
  docstring  "same as defn, yielding non-public def"
  eldoc      (("name" "&" "decls"))
  name       "defn-"
  ns         "clojure.core"
  status     ("done")
  type       "macro"
)
(-->
  id         "16"
  op         "eldoc"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:20.728119421"
  context    "(defn- __prefix__ [system]
  (component/stop @system))"
  ns         #("integration.integration.specification-test" 0 42 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil help-echo cider--help-echo fontified t))
  sym        "cleanup"
)
(<--
  id         "16"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:20.730636909"
  status     ("done" "no-eldoc")
)
(-->
  id         "17"
  op         "load-file"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:25.013375340"
  file       "(ns integration.integration.specification-test
  (:require [..."
  file-name  "specification_test.clj"
  file-path  "/home/roman/workspace/nu/bloqueto/test/integration/integrati..."
)
(<--
  id         "13"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:28.188377350"
  ns         "integration.integration.specification-test"
  value      "nil"
)
(<--
  id         "13"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:28.197366516"
  status     ("done")
)
(<--
  id         "17"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:28.205700588"
  value      "#'integration.integration.specification-test/test-specificat..."
)
(<--
  id         "17"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:39:28.212097716"
  status     ("done")
)
(<--
  id                 "13"
  session            "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp         "2024-03-08 14:39:28.733572450"
  changed-namespaces (dict ...)
  repl-type          "clj"
  status             ("state")
)
(-->
  id         "18"
  op         "eldoc"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:40:56.232461899"
  context    "(defn __prefix__ [system]
  {:system system})"
  ns         #("integration.integration.specification-test" 0 42 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil help-echo cider--help-echo fontified t))
  sym        "initial-state"
)
(-->
  id         "19"
  op         "eldoc"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:40:57.885085997"
  context    "(__prefix__ initial-state [system]
  {:system system})"
  ns         #("integration.integration.specification-test" 0 42 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil help-echo cider--help-echo fontified t))
  sym        "defn"
)
(-->
  id         "20"
  op         "eldoc"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:40:59.497999722"
  context    "(defn __prefix__ [system]
  {:system system})"
  ns         #("integration.integration.specification-test" 0 42 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil help-echo cider--help-echo fontified t))
  sym        "initial-state"
)
(-->
  id         "21"
  op         "eldoc"
  session    "e0ee51fd-133a-4efa-86bb-4ead5c385570"
  time-stamp "2024-03-08 14:41:05.766145136"
  context    "(__prefix__ initial-state [system]
  {:system system})"
  ns         #("integration.integration.specification-test" 0 42 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil help-echo cider--help-echo fontified t))
  sym        "defn"
)

There are a couple of eldoc requests that have a reponse. The last 4 requests don't have a response and this is were it crashes. It looks like nrepl-log-message that should print the response is already affected by this.

In the stacktrace above there is a line that starts with:

nrepl--dispatch-response((dict "macro" "type" ("done") "status" ... 

Am I correct that the list is in the wrong order? And it should actually be:

nrepl--dispatch-response((dict "type" "macro" "status" ("done")  ... 
vemv commented 4 months ago

Am I correct that the list is in the wrong order? And it should actually be:

That would seem correct to me

One thing that you could do is to locally modify https://github.com/clojure-emacs/cider-nrepl/blob/95ce24bf1f40ef566aed2d073a41c943723cf1bd/src/cider/nrepl/middleware/info.clj#L131-L138 so that it tap>s the sent values.

Then you'd locally install cider-nrepl and use it (make sure that the versions match, e.g. install as 0.46.0, specify that same version in your setup).

Then, favor cider-connect over cider-jack-in.

Finallly, when cider crashes, connect to the same process with e.g. lein repl :connect.

Then inspect the tap>ped values.

(You can also just swap! them to an atom if that's easier, of course)

If you verify the hypothesis that cider-nrepl is producing invalid responses, we could further investigate.

You could also temporarily hack it to return {:status :no-eldoc} if the response looks invalid.

Cheers - V

vemv commented 4 months ago

On second thoughts, my suggestion may be pretty useless. The issue appears to boil down to:

This plist looks like it contains 2 NREPL responses, but somehow mixed

I wonder what is mixing them - does that happen at cider.el level, or at the JVM (nrepl) level?

You could try adding some nrepl-wide logging. That can be done with custom nrepl middleware.

Assuming it's Elisp that's mixing them, we have changed nothing in this area for a long time. Our nrepl-client.el is very stable code.

Last but not least, is there anything remarkable in your stack?

r0man commented 4 months ago

@vemv, I think I found the issue. There's a NREPL client for Guile Scheme, which I had on my load path:

https://git.sr.ht/~abcdw/emacs-arei/tree/master/item/arei-nrepl.el

It seems it ships an incompatible clone of nrepl-dict.el which is causing those nrepl dictionaries to be reversed. I haven't check what exactly is the issue, but removing this package from my load path seems to fix the issue.

@abcdw Do you think you could prefix the functions in your NREPL module with arei- or in order to avoid this?

r0man commented 4 months ago

@vemv Thanks for the hints. I didn't realize those nrepl functions in the stacktrace came from this other package. Let's see if @abcdw can do anything about this.

bbatsov commented 4 months ago

This issue also reminded me of the failed attempt to extract a generic nREPL client from CIDER in the past (that's why the function in nrepl-client.el have a different prefix (nrepl- instead of cider-).

r0man commented 4 months ago

@bbatsov Yeah, I think having a separate nrepl package would be useful to people who build other clients. nrepl-dict.el looks like it would be ready, nrepl-client.el however still has many references to cider. Maybe one day :)

bbatsov commented 4 months ago

Yeah, it's very doable but it was never a big priority for various reasons. Maybe one day indeed.

abcdw commented 4 months ago

@r0man Yep, I can prefix them, but not sure about the timeline :)

r0man commented 4 months ago

@abcdw Perfect, thank you!

abcdw commented 4 months ago

On 2024-03-09 06:54, r0man wrote:

@abcdw Perfect, thank you!

Accomplished in 0.9.3.

https://git.sr.ht/~abcdw/emacs-arei/commit/3365b3e5468664957f3be526ebca7b0cddafce20

-- Best regards, Andrew Tropin

r0man commented 4 months ago

Thank you

On Fri, Mar 15, 2024, 08:00 Andrew Tropin @.***> wrote:

On 2024-03-09 06:54, r0man wrote:

@abcdw Perfect, thank you!

Accomplished in 0.9.3.

https://git.sr.ht/~abcdw/emacs-arei/commit/3365b3e5468664957f3be526ebca7b0cddafce20

-- Best regards, Andrew Tropin

— Reply to this email directly, view it on GitHub https://github.com/clojure-emacs/cider/issues/3630#issuecomment-1999050981, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAAFIPSLLMYBDOAOACK3U2TYYKL7JAVCNFSM6AAAAABEM2OYCGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSOJZGA2TAOJYGE . You are receiving this because you were mentioned.Message ID: @.***>