Flaky/failing Windows integration tests

[vemv]

Over the last few days, our Windows integration tests have tended to look like this:

...apparently it's always a single integration test that fails.

@ikappaki , would you like to have a look?

Thanks - V

[ikappaki]

Hi @vemv,

preliminary analysis shows that in the failing case, that just before the nrepl-client is in between of closing the two session clones with the nrepl-server, it issues a classpath op and it all goes bad from there on

expected sequence closes the two sessions in ids 9/10:

:BUFFER "*nrepl-messages Temp/4zGl15:localhost:52114(clj)*<2>"
(-->
  id         "1"
  op         "clone"
  time-stamp "2023-08-24 21:59:40.840532000"
)
(<--
  id          "1"
  session     "feb75440-c338-4e3f-ac34-5199941cbc36"
  time-stamp  "2023-08-24 21:59:40.848239000"
  new-session "7dcac43a-12f7-4854-8970-af05190f3f91"
  status      ("done")
)
(-->
  id         "2"
  op         "clone"
  time-stamp "2023-08-24 21:59:40.879551000"
)
(<--
  id          "2"
  session     "360b31d7-f472-409c-a619-ebf43f7d34be"
  time-stamp  "2023-08-24 21:59:40.883039000"
  new-session "638dc831-2908-4ffc-b710-ebb0b56a4885"
  status      ("done")
)
(-->
  id         "3"
  op         "describe"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:40.911048000"
)
(<--
  id         "3"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:40.922730000"
  aux        (dict ...)
  ops        (dict ...)
  status     ("done")
  versions   (dict ...)
)
(-->
  id                                 "4"
  op                                 "eval"
  session                            "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp                         "2023-08-24 21:59:40.944550000"
  code                               "(when-let [requires (resolve 'clojure.main/repl-requires)]
 ..."
  column                             1
  file                               "*cider-repl Temp/4zGl15:localhost:52114(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    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:40.982852000"
  value      "nil"
)
(<--
  id         "4"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:40.983040000"
  ns         "user"
)
(<--
  id         "4"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:40.983140000"
  status     ("done")
)
(-->
  id         "5"
  op         "out-subscribe"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:40.983382000"
)
(-->
  id                                 "6"
  op                                 "init-debugger"
  session                            "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp                         "2023-08-24 21:59:40.983586000"
  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         "eval"
  session    "638dc831-2908-4ffc-b710-ebb0b56a4885"
  time-stamp "2023-08-24 21:59:40.983866000"
  code       "cljs.core/demunge"
)
(<--
  id            "5"
  session       "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp    "2023-08-24 21:59:41.073251000"
  out-subscribe "7dcac43a-12f7-4854-8970-af05190f3f91"
  status        ("done")
)
(<--
  id         "7"
  session    "638dc831-2908-4ffc-b710-ebb0b56a4885"
  time-stamp "2023-08-24 21:59:43.118323000"
  err        "Syntax error (ClassNotFoundException) compiling at (REPL:0:0..."
)
(<--
  id         "7"
  session    "638dc831-2908-4ffc-b710-ebb0b56a4885"
  time-stamp "2023-08-24 21:59:43.118659000"
  ex         "class clojure.lang.Compiler$CompilerException"
  root-ex    "class clojure.lang.Compiler$CompilerException"
  status     ("eval-error")
)
(<--
  id         "7"
  session    "638dc831-2908-4ffc-b710-ebb0b56a4885"
  time-stamp "2023-08-24 21:59:43.119005000"
  status     ("done")
)
(-->
  id         "8"
  op         "eval"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:43.147016000"
  code       "(print :clojure? (some? (clojure-version)))"
  ns         "user"
)
(<--
  id         "8"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:43.149535000"
  out        ":clojure? true"
)
(<--
  id         "8"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:43.150283000"
  ns         "user"
  value      "nil"
)
(<--
  id         "8"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:43.150454000"
  status     ("done")
)
(<--
  id                 "7"
  session            "638dc831-2908-4ffc-b710-ebb0b56a4885"
  time-stamp         "2023-08-24 21:59:43.395158000"
  changed-namespaces (dict ...)
  repl-type          "clj"
  status             ("state")
)
(-->
  id         "9"
  op         "close"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:43.395436000"
)
(<--
  id                 "8"
  session            "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp         "2023-08-24 21:59:43.414035000"
  changed-namespaces (dict ...)
  repl-type          "clj"
  status             ("state")
)
(<--
  id         "9"
  session    "7dcac43a-12f7-4854-8970-af05190f3f91"
  time-stamp "2023-08-24 21:59:43.499543000"
  status     ("done" "session-closed")
)
(-->
  id         "10"
  op         "close"
  session    "638dc831-2908-4ffc-b710-ebb0b56a4885"
  time-stamp "2023-08-24 21:59:43.528956000"
)
(<--
  id         "10"
  session    "638dc831-2908-4ffc-b710-ebb0b56a4885"
  time-stamp "2023-08-24 21:59:43.641159000"
  status     ("done" "session-closed")
)

failing sequence which also tries to close sessions in 9/10, but it issues a classpath op in 11, before 10 has a chance to get the response back. It then is stuck in an endless bouncing until the test timeouts. The error is clearly indicating with the server responding that the session is unknown ( status ("done" "unknown-session" "error")). Has there been any recent change around closing the connection? The nrepl client shouldn't be issuing any commands to the server while we are exiting ... The integration tests issue (cider-quit repl-buffer) to exit the client.

2023-08-24T15:44:27.4148077Z              :BUFFER "*nrepl-messages Temp/5rfwwO:localhost:50243(clj)*<2>"
2023-08-24T15:44:27.4148608Z [02:53.674]  (-->
2023-08-24T15:44:27.4150859Z                id         "1"
2023-08-24T15:44:27.4151464Z                op         "clone"
2023-08-24T15:44:27.4152053Z                time-stamp "2023-08-24 15:44:08.793325000"
2023-08-24T15:44:27.4152469Z              )
2023-08-24T15:44:27.4152877Z              (<--
2023-08-24T15:44:27.4153263Z                id          "1"
2023-08-24T15:44:27.4153895Z                session     "fac8cdc7-95ec-4de3-86a5-e66e763f62a4"
2023-08-24T15:44:27.4154526Z                time-stamp  "2023-08-24 15:44:08.820172000"
2023-08-24T15:44:27.4155143Z                new-session "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4155601Z                status      ("done")
2023-08-24T15:44:27.4156285Z              )
2023-08-24T15:44:27.4157726Z              (-->
2023-08-24T15:44:27.4158018Z                id         "2"
2023-08-24T15:44:27.4158366Z                op         "clone"
2023-08-24T15:44:27.4158829Z                time-stamp "2023-08-24 15:44:08.839442000"
2023-08-24T15:44:27.4159130Z              )
2023-08-24T15:44:27.4159407Z              (<--
2023-08-24T15:44:27.4159701Z                id          "2"
2023-08-24T15:44:27.4160502Z                session     "0195b66c-f447-454c-b438-458db0b01a65"
2023-08-24T15:44:27.4161060Z                time-stamp  "2023-08-24 15:44:08.842014000"
2023-08-24T15:44:27.4161595Z                new-session "0ec7b7e0-c528-47fd-974b-fd2c1ca3b692"
2023-08-24T15:44:27.4161972Z                status      ("done")
2023-08-24T15:44:27.4162253Z              )
2023-08-24T15:44:27.4162552Z              (-->
2023-08-24T15:44:27.4162820Z                id         "3"
2023-08-24T15:44:27.4163368Z                op         "describe"
2023-08-24T15:44:27.4163998Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4164494Z                time-stamp "2023-08-24 15:44:08.870695000"
2023-08-24T15:44:27.4164788Z              )
2023-08-24T15:44:27.4165188Z              (<--
2023-08-24T15:44:27.4165556Z                id         "3"
2023-08-24T15:44:27.4166129Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4166733Z                time-stamp "2023-08-24 15:44:08.879801000"
2023-08-24T15:44:27.4167179Z                aux        (dict ...)
2023-08-24T15:44:27.4167598Z                ops        (dict ...)
2023-08-24T15:44:27.4168279Z                status     ("done")
2023-08-24T15:44:27.4168698Z                versions   (dict ...)
2023-08-24T15:44:27.4169069Z              )
2023-08-24T15:44:27.4169422Z              (-->
2023-08-24T15:44:27.4169837Z                id                                 "4"
2023-08-24T15:44:27.4170288Z                op                                 "eval"
2023-08-24T15:44:27.4170872Z                session                            "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4171547Z                time-stamp                         "2023-08-24 15:44:08.904172000"
2023-08-24T15:44:27.4172321Z                code                               "(when-let [requires (resolve 'clojure.main/repl-requires)]
2023-08-24T15:44:27.4172790Z               ..."
2023-08-24T15:44:27.4173220Z                column                             1
2023-08-24T15:44:27.4173907Z                file                               "*cider-repl Temp/5rfwwO:localhost:50243(clj)*"
2023-08-24T15:44:27.4174560Z                inhibit-cider-middleware           "true"
2023-08-24T15:44:27.4175045Z                line                               43
2023-08-24T15:44:27.4175619Z                nrepl.middleware.print/buffer-size 4096
2023-08-24T15:44:27.4176197Z                nrepl.middleware.print/options     (dict ...)
2023-08-24T15:44:27.4176790Z                nrepl.middleware.print/print       "cider.nrepl.pprint/pprint"
2023-08-24T15:44:27.4177965Z                nrepl.middleware.print/quota       1048576
2023-08-24T15:44:27.4178648Z                nrepl.middleware.print/stream?     "1"
2023-08-24T15:44:27.4179069Z              )
2023-08-24T15:44:27.4179490Z              (<--
2023-08-24T15:44:27.4179902Z                id         "4"
2023-08-24T15:44:27.4180538Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4181161Z                time-stamp "2023-08-24 15:44:08.988485000"
2023-08-24T15:44:27.4181592Z                value      "nil"
2023-08-24T15:44:27.4182720Z              )
2023-08-24T15:44:27.4183164Z              (<--
2023-08-24T15:44:27.4183537Z                id         "4"
2023-08-24T15:44:27.4184115Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4184715Z                time-stamp "2023-08-24 15:44:08.988835000"
2023-08-24T15:44:27.4185146Z                ns         "user"
2023-08-24T15:44:27.4185533Z              )
2023-08-24T15:44:27.4185902Z              (<--
2023-08-24T15:44:27.4186612Z                id         "4"
2023-08-24T15:44:27.4187445Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4189472Z                time-stamp "2023-08-24 15:44:08.989309000"
2023-08-24T15:44:27.4190079Z                status     ("done")
2023-08-24T15:44:27.4190459Z              )
2023-08-24T15:44:27.4191175Z              (-->
2023-08-24T15:44:27.4192322Z                id         "5"
2023-08-24T15:44:27.4192940Z                op         "out-subscribe"
2023-08-24T15:44:27.4193584Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4194191Z                time-stamp "2023-08-24 15:44:08.989853000"
2023-08-24T15:44:27.4194586Z              )
2023-08-24T15:44:27.4194976Z              (-->
2023-08-24T15:44:27.4195394Z                id                                 "6"
2023-08-24T15:44:27.4195956Z                op                                 "init-debugger"
2023-08-24T15:44:27.4196650Z                session                            "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4197313Z                time-stamp                         "2023-08-24 15:44:08.990255000"
2023-08-24T15:44:27.4197926Z                nrepl.middleware.print/buffer-size 4096
2023-08-24T15:44:27.4200250Z                nrepl.middleware.print/options     (dict ...)
2023-08-24T15:44:27.4200896Z                nrepl.middleware.print/print       "cider.nrepl.pprint/pprint"
2023-08-24T15:44:27.4201464Z                nrepl.middleware.print/quota       1048576
2023-08-24T15:44:27.4202270Z                nrepl.middleware.print/stream?     "1"
2023-08-24T15:44:27.4203326Z              )
2023-08-24T15:44:27.4203794Z              (-->
2023-08-24T15:44:27.4204163Z                id         "7"
2023-08-24T15:44:27.4204562Z                op         "eval"
2023-08-24T15:44:27.4205161Z                session    "0ec7b7e0-c528-47fd-974b-fd2c1ca3b692"
2023-08-24T15:44:27.4205777Z                time-stamp "2023-08-24 15:44:08.990733000"
2023-08-24T15:44:27.4206231Z                code       "cljs.core/demunge"
2023-08-24T15:44:27.4206603Z              )
2023-08-24T15:44:27.4206966Z              (<--
2023-08-24T15:44:27.4207382Z                id            "5"
2023-08-24T15:44:27.4207968Z                session       "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4208588Z                time-stamp    "2023-08-24 15:44:09.182645000"
2023-08-24T15:44:27.4209213Z                out-subscribe "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4210344Z                status        ("done")
2023-08-24T15:44:27.4210722Z              )
2023-08-24T15:44:27.4211144Z              (<--
2023-08-24T15:44:27.4211502Z                id         "7"
2023-08-24T15:44:27.4212122Z                session    "0ec7b7e0-c528-47fd-974b-fd2c1ca3b692"
2023-08-24T15:44:27.4212729Z                time-stamp "2023-08-24 15:44:13.449877000"
2023-08-24T15:44:27.4213815Z                err        "Syntax error (ClassNotFoundException) compiling at (REPL:0:0..."
2023-08-24T15:44:27.4214381Z              )
2023-08-24T15:44:27.4214807Z              (<--
2023-08-24T15:44:27.4215169Z                id         "7"
2023-08-24T15:44:27.4215756Z                session    "0ec7b7e0-c528-47fd-974b-fd2c1ca3b692"
2023-08-24T15:44:27.4216421Z                time-stamp "2023-08-24 15:44:13.450106000"
2023-08-24T15:44:27.4216976Z                ex         "class clojure.lang.Compiler$CompilerException"
2023-08-24T15:44:27.4217699Z                root-ex    "class clojure.lang.Compiler$CompilerException"
2023-08-24T15:44:27.4218306Z                status     ("eval-error")
2023-08-24T15:44:27.4218681Z              )
2023-08-24T15:44:27.4219048Z              (<--
2023-08-24T15:44:27.4219405Z                id         "7"
2023-08-24T15:44:27.4219980Z                session    "0ec7b7e0-c528-47fd-974b-fd2c1ca3b692"
2023-08-24T15:44:27.4221211Z                time-stamp "2023-08-24 15:44:13.450428000"
2023-08-24T15:44:27.4221670Z                status     ("done")
2023-08-24T15:44:27.4222032Z              )
2023-08-24T15:44:27.4222430Z              (-->
2023-08-24T15:44:27.4222783Z                id         "8"
2023-08-24T15:44:27.4256767Z                op         "eval"
2023-08-24T15:44:27.4257389Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4258403Z                time-stamp "2023-08-24 15:44:13.470067000"
2023-08-24T15:44:27.4259039Z                code       "(print :clojure? (some? (clojure-version)))"
2023-08-24T15:44:27.4259439Z                ns         "user"
2023-08-24T15:44:27.4259713Z              )
2023-08-24T15:44:27.4259998Z              (<--
2023-08-24T15:44:27.4260274Z                id         "8"
2023-08-24T15:44:27.4260759Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4261291Z                time-stamp "2023-08-24 15:44:13.474692000"
2023-08-24T15:44:27.4261655Z                out        ":clojure? true"
2023-08-24T15:44:27.4261942Z              )
2023-08-24T15:44:27.4262221Z              (<--
2023-08-24T15:44:27.4262522Z                id         "8"
2023-08-24T15:44:27.4262998Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4263496Z                time-stamp "2023-08-24 15:44:13.474852000"
2023-08-24T15:44:27.4263844Z                ns         "user"
2023-08-24T15:44:27.4264154Z                value      "nil"
2023-08-24T15:44:27.4264425Z              )
2023-08-24T15:44:27.4264758Z              (<--
2023-08-24T15:44:27.4265601Z                id         "8"
2023-08-24T15:44:27.4266094Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4266912Z                time-stamp "2023-08-24 15:44:13.474983000"
2023-08-24T15:44:27.4267283Z                status     ("done")
2023-08-24T15:44:27.4267605Z              )
2023-08-24T15:44:27.4267905Z              (-->
2023-08-24T15:44:27.4268171Z                id         "9"
2023-08-24T15:44:27.4268477Z                op         "close"
2023-08-24T15:44:27.4268953Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4269440Z                time-stamp "2023-08-24 15:44:13.671213000"
2023-08-24T15:44:27.4269731Z              )
2023-08-24T15:44:27.4270005Z              (<--
2023-08-24T15:44:27.4270279Z                id         "9"
2023-08-24T15:44:27.4270749Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4271232Z                time-stamp "2023-08-24 15:44:13.781245000"
2023-08-24T15:44:27.4271718Z                status     ("done" "session-closed")
2023-08-24T15:44:27.4272027Z              )
2023-08-24T15:44:27.4272351Z              (-->
2023-08-24T15:44:27.4272643Z                id         "10"
2023-08-24T15:44:27.4272951Z                op         "close"
2023-08-24T15:44:27.4273446Z                session    "0ec7b7e0-c528-47fd-974b-fd2c1ca3b692"
2023-08-24T15:44:27.4273951Z                time-stamp "2023-08-24 15:44:13.812306000"
2023-08-24T15:44:27.4274247Z              )
2023-08-24T15:44:27.4274543Z              (-->
2023-08-24T15:44:27.4274831Z                id         "11"
2023-08-24T15:44:27.4275153Z                op         "classpath"
2023-08-24T15:44:27.4275642Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4276141Z                time-stamp "2023-08-24 15:44:13.850649000"
2023-08-24T15:44:27.4276438Z              )
2023-08-24T15:44:27.4276715Z              (<--
2023-08-24T15:44:27.4277041Z                id         "11"
2023-08-24T15:44:27.4277529Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4278019Z                time-stamp "2023-08-24 15:44:13.851701000"
2023-08-24T15:44:27.4278541Z                status     ("done" "unknown-session" "error")
2023-08-24T15:44:27.4278854Z              )
2023-08-24T15:44:27.4279155Z              (-->
2023-08-24T15:44:27.4279454Z                id              "12"
2023-08-24T15:44:27.4279856Z                op              "ns-list"
2023-08-24T15:44:27.4281405Z                session         "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4281986Z                time-stamp      "2023-08-24 15:44:13.867317000"
2023-08-24T15:44:27.4282546Z                exclude-regexps ("^cider.nrepl" "^refactor-nrepl" "^nrepl")
2023-08-24T15:44:27.4283168Z              )
2023-08-24T15:44:27.4283528Z              (-->
2023-08-24T15:44:27.4283854Z                id         "13"
2023-08-24T15:44:27.4284193Z                op         "classpath"
2023-08-24T15:44:27.4284694Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4285189Z                time-stamp "2023-08-24 15:44:13.891912000"
2023-08-24T15:44:27.4285493Z              )
2023-08-24T15:44:27.4285771Z              (<--
2023-08-24T15:44:27.4286063Z                id         "12"
2023-08-24T15:44:27.4286538Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4287029Z                time-stamp "2023-08-24 15:44:13.892871000"
2023-08-24T15:44:27.4287520Z                status     ("done" "unknown-session" "error")
2023-08-24T15:44:27.4287837Z              )
2023-08-24T15:44:27.4288114Z              (<--
2023-08-24T15:44:27.4288408Z                id         "13"
2023-08-24T15:44:27.4288974Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4289464Z                time-stamp "2023-08-24 15:44:13.893242000"
2023-08-24T15:44:27.4290173Z                status     ("done" "unknown-session" "error")
2023-08-24T15:44:27.4290488Z              )
2023-08-24T15:44:27.4290792Z              (-->
2023-08-24T15:44:27.4291092Z                id              "14"
2023-08-24T15:44:27.4291814Z                op              "ns-list"
2023-08-24T15:44:27.4292313Z                session         "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4292821Z                time-stamp      "2023-08-24 15:44:13.920988000"
2023-08-24T15:44:27.4293362Z                exclude-regexps ("^cider.nrepl" "^refactor-nrepl" "^nrepl")
2023-08-24T15:44:27.4293716Z              )
2023-08-24T15:44:27.4293993Z              (<--
2023-08-24T15:44:27.4294287Z                id         "10"
2023-08-24T15:44:27.4294790Z                session    "0ec7b7e0-c528-47fd-974b-fd2c1ca3b692"
2023-08-24T15:44:27.4295296Z                time-stamp "2023-08-24 15:44:13.921673000"
2023-08-24T15:44:27.4295773Z                status     ("done" "session-closed")
2023-08-24T15:44:27.4296089Z              )
2023-08-24T15:44:27.4296366Z              (<--
2023-08-24T15:44:27.4296661Z                id         "14"
2023-08-24T15:44:27.4297134Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4297618Z                time-stamp "2023-08-24 15:44:13.922372000"
2023-08-24T15:44:27.4298109Z                status     ("done" "unknown-session" "error")
2023-08-24T15:44:27.4298425Z              )
2023-08-24T15:44:27.4298724Z              (-->
2023-08-24T15:44:27.4299012Z                id         "15"
2023-08-24T15:44:27.4299339Z                op         "classpath"
2023-08-24T15:44:27.4299857Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4300345Z                time-stamp "2023-08-24 15:44:13.954599000"
2023-08-24T15:44:27.4300644Z              )
2023-08-24T15:44:27.4300922Z              (<--
2023-08-24T15:44:27.4301210Z                id         "15"
2023-08-24T15:44:27.4301677Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4302175Z                time-stamp "2023-08-24 15:44:13.956000000"
2023-08-24T15:44:27.4302669Z                status     ("done" "unknown-session" "error")
2023-08-24T15:44:27.4302987Z              )
2023-08-24T15:44:27.4303283Z              (-->
2023-08-24T15:44:27.4303580Z                id              "16"
2023-08-24T15:44:27.4303973Z                op              "ns-list"
2023-08-24T15:44:27.4304464Z                session         "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4305708Z                time-stamp      "2023-08-24 15:44:13.983422000"
2023-08-24T15:44:27.4306281Z                exclude-regexps ("^cider.nrepl" "^refactor-nrepl" "^nrepl")
2023-08-24T15:44:27.4306639Z              )
2023-08-24T15:44:27.4306918Z              (<--
2023-08-24T15:44:27.4307597Z                id         "16"
2023-08-24T15:44:27.4308136Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4308644Z                time-stamp "2023-08-24 15:44:13.985121000"
2023-08-24T15:44:27.4309136Z                status     ("done" "unknown-session" "error")
2023-08-24T15:44:27.4309455Z              )
2023-08-24T15:44:27.4309756Z              (-->
2023-08-24T15:44:27.4310053Z                id         "17"
2023-08-24T15:44:27.4310447Z                op         "classpath"
2023-08-24T15:44:27.4310938Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4311455Z                time-stamp "2023-08-24 15:44:14.016860000"
2023-08-24T15:44:27.4311752Z              )
2023-08-24T15:44:27.4312033Z              (<--
2023-08-24T15:44:27.4312326Z                id         "17"
2023-08-24T15:44:27.4312802Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4313297Z                time-stamp "2023-08-24 15:44:14.018431000"
2023-08-24T15:44:27.4313794Z                status     ("done" "unknown-session" "error")
2023-08-24T15:44:27.4314297Z              )
2023-08-24T15:44:27.4314613Z              (-->
2023-08-24T15:44:27.4314912Z                id              "18"
2023-08-24T15:44:27.4315312Z                op              "ns-list"
2023-08-24T15:44:27.4315811Z                session         "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:27.4316324Z                time-stamp      "2023-08-24 15:44:14.045883000"
2023-08-24T15:44:28.4285695Z                exclude-regexps ("^cider.nrepl" "^refactor-nrepl" "^nrepl")
2023-08-24T15:44:28.4286427Z              )
2023-08-24T15:44:28.4286842Z              (<--
2023-08-24T15:44:28.4287322Z                id         "18"
2023-08-24T15:44:28.4287933Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:28.4288561Z                time-stamp "2023-08-24 15:44:14.047290000"
2023-08-24T15:44:28.4289195Z                status     ("done" "unknown-session" "error")
2023-08-24T15:44:28.4289618Z              )
2023-08-24T15:44:28.4290044Z              (-->
2023-08-24T15:44:28.4290457Z                id         "19"
2023-08-24T15:44:28.4291018Z                op         "classpath"
2023-08-24T15:44:28.4291601Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:28.4292182Z                time-stamp "2023-08-24 15:44:14.079133000"
2023-08-24T15:44:28.4292554Z              )
2023-08-24T15:44:28.4292912Z              (<--
2023-08-24T15:44:28.4293283Z                id         "19"
2023-08-24T15:44:28.4293870Z                session    "cc193a91-6c6f-4be0-9075-4c6367999557"
2023-08-24T15:44:28.4294449Z                time-stamp "2023-08-24 15:44:14.080408000"
2023-08-24T15:44:28.4295029Z                status     ("done" "unknown-session" "error")
2023-08-24T15:44:28.4295628Z              )
....

thanks

[vemv]

Hi @ikappaki , thanks for the great analysis!

I am able to see things more clearly now.

The classpath and ns-list ops suggest that the code that is triggering those requests is:

cider/cider-repl.el

Lines 1771 to 1780 in 73f0d05

	(let* ((classpath (or (process-get proc :cached-classpath)
	(let ((cp (with-current-buffer repl
	(cider-classpath-entries))))
	(process-put proc :cached-classpath cp)
	cp)))
	(ns-list (or (process-get proc :all-namespaces)
	(let ((ns-list (with-current-buffer repl
	(cider-sync-request:ns-list))))
	(process-put proc :all-namespaces ns-list)
	ns-list)))

(a bit of context: the classpath request has always been there, but the ns-list request is a recent addition)

I wonder if we could avoid sending those requests if we detected that the session was closed. It would seem a fix that users would also benefit from.

Cheers - V

[ikappaki]

Hi @vemv,

I wonder if we could avoid sending those requests if we detected that the session was closed. It would seem a fix that users would also benefit from.

Yes, perhaps we could put something in the session when indicating that we are in the process of closing and have sync-req check this?

the other scenario is that the server never responded to the closing of the second session (the "tooling" session), and the cider nrepl client carried on witth its normal job?

request to close the connection

cider/cider-connection.el

Lines 197 to 227 in 73f0d05

	(defun cider--close-connection (repl &optional no-kill)
	"Close connection associated with REPL.
	When NO-KILL is non-nil stop the connection but don't kill the REPL
	buffer."
	(when (buffer-live-p repl)
	(with-current-buffer repl
	(when spinner-current (spinner-stop))
	(when nrepl-tunnel-buffer
	(cider--close-buffer nrepl-tunnel-buffer))
	(when no-kill
	;; inform sentinel not to kill the server, if any
	(thread-first
	(get-buffer-process repl)
	(process-plist)
	(plist-put :keep-server t))))
	(let ((proc (get-buffer-process repl)))
	(when (and (process-live-p proc)
	(or (not nrepl-server-buffer)
	;; Sync request will hang if the server is dead.
	(process-live-p (get-buffer-process nrepl-server-buffer))))
	(nrepl-sync-request:close repl)
	;; give a chance to the REPL to respond to the closing of the connection
	(sleep-for 0.5)
	(delete-process proc)))
	(when-let* ((messages-buffer (and nrepl-log-messages
	(nrepl-messages-buffer repl))))
	(kill-buffer messages-buffer))
	(unless no-kill
	(kill-buffer repl)))
	(when repl
	(sesman-remove-object 'CIDER nil repl (not no-kill) t)))

the close sync req (sending the two closing reqs, the one the server never response I believe is the tooling)

cider/nrepl-client.el

Lines 1041 to 1044 in 73f0d05

	(defun nrepl-sync-request:close (connection)
	"Sent a :close request to close CONNECTION's SESSION."
	(nrepl-send-sync-request '("op" "close") connection)
	(nrepl-send-sync-request '("op" "close") connection nil t)) ;; close tooling session

The sync request, which will time out if no response comes back

cider/nrepl-client.el

Lines 935 to 980 in 73f0d05

	(defun nrepl-send-sync-request (request connection &optional abort-on-input tooling)
	"Send REQUEST to the nREPL server synchronously using CONNECTION.
	Hold till final \"done\" message has arrived and join all response messages
	of the same \"op\" that came along.
	If ABORT-ON-INPUT is non-nil, the function will return nil at the first
	sign of user input, so as not to hang the interface.
	If TOOLING, use the tooling session rather than the standard session."
	(let* ((time0 (current-time))
	(response (cons 'dict nil))
	(nrepl-ongoing-sync-request t)
	status)
	(nrepl-send-request request
	(lambda (resp) (nrepl--merge response resp))
	connection
	tooling)
	(while (and (not (member "done" status))
	(not (and abort-on-input
	(input-pending-p))))
	(setq status (nrepl-dict-get response "status"))
	;; If we get a need-input message then the repl probably isn't going
	;; anywhere, and we'll just timeout. So we forward it to the user.
	(if (member "need-input" status)
	(progn (cider-need-input (current-buffer))
	;; If the used took a few seconds to respond, we might
	;; unnecessarily timeout, so let's reset the timer.
	(setq time0 (current-time)))
	;; break out in case we don't receive a response for a while
	(when (and nrepl-sync-request-timeout
	(time-less-p
	nrepl-sync-request-timeout
	(time-subtract nil time0)))
	(error "Sync nREPL request timed out %s after %s secs" request nrepl-sync-request-timeout)))
	;; Clean up the response, otherwise we might repeatedly ask for input.
	(nrepl-dict-put response "status" (remove "need-input" status))
	(accept-process-output nil 0.01))
	;; If we couldn't finish, return nil.
	(when (member "done" status)
	(nrepl-dbind-response response (ex err eval-error pp-stacktrace id)
	(when (and ex err)
	(cond (eval-error (funcall nrepl-err-handler))
	(pp-stacktrace (cider--render-stacktrace-causes
	pp-stacktrace (remove "done" status))))) ;; send the error type
	(when id
	(with-current-buffer connection
	(nrepl--mark-id-completed id)))
	response))))

and we see that the close request has indeed timed out in the log

2023-08-24T15:44:28.5816419Z Traceback (most recent call last):
2023-08-24T15:44:28.5816689Z   signal(error ("Sync nREPL request timed out (op close) after 10 secs"))
2023-08-24T15:44:28.5817002Z error: (error "Sync nREPL request timed out (op close) after 10 secs")

[vemv]

This was fixed with #3435

Again, thanks for the analysis, which lead me to a useful direction.

Perhaps there are things that can be improved, namely:

Yes, perhaps we could put something in the session when indicating that we are in the process of closing and have sync-req check this?

Feel free to create an issue for that.