ClojureScript

Lockup reconnecting browser REPL

Details

  • Type: Defect Defect
  • Status: Open Open
  • Priority: Major Major
  • Resolution: Unresolved
  • Affects Version/s: None
  • Fix Version/s: None
  • Component/s: None
  • Labels:
    None

Description

Quitting and attempting to reconnect using the same JVM / REPL env can lock up:

$ clj
Clojure 1.9.0
user=> (require '[cljs.repl :as repl])
nil
user=> (require '[cljs.repl.browser :as browser])
nil
user=> (def env (browser/repl-env))
#'user/env
user=> (repl/repl env)
ClojureScript 1.10.339
cljs.user=> 3
3
cljs.user=> :cljs/quit
nil
user=> (repl/repl env)

At this point, things are locked up. Here are the thread stacks:

$ jstack 97709
2018-10-13 13:26:33
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.172-b11 mixed mode):

"Attach Listener" #156 daemon prio=9 os_prio=31 tid=0x00007ff1d4a14000 nid=0x9f0b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"clojure-agent-send-off-pool-1" #14 prio=5 os_prio=31 tid=0x00007ff1d4963800 nid=0x4003 waiting on condition [0x000070000cd57000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000006c1859760> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

"clojure-agent-send-off-pool-0" #13 prio=5 os_prio=31 tid=0x00007ff1d41e9800 nid=0x4203 waiting on condition [0x000070000cc54000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000006c1859760> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

"process reaper" #12 daemon prio=10 os_prio=31 tid=0x00007ff1d4967800 nid=0x3c03 waiting on condition [0x000070000cb51000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000006c209c4a8> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

"Service Thread" #8 daemon prio=9 os_prio=31 tid=0x00007ff1d206a800 nid=0x4403 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007ff1d1814000 nid=0x3603 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007ff1d2057800 nid=0x3503 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007ff1d2058800 nid=0x4703 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007ff1d2057000 nid=0x490b runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007ff1d2018000 nid=0x5103 in Object.wait() [0x000070000c411000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000006c01466f8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	- locked <0x00000006c01466f8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007ff1d2017800 nid=0x2e03 in Object.wait() [0x000070000c30e000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000006c0146980> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x00000006c0146980> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=31 tid=0x00007ff1d2005000 nid=0x2103 waiting on condition [0x000070000bcfa000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x0000000792c08ed8> (a java.util.concurrent.CountDownLatch$Sync)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
	at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
	at clojure.core$promise$reify__8144.deref(core.clj:7029)
	at clojure.core$deref.invokeStatic(core.clj:2312)
	at clojure.core$deref.invoke(core.clj:2298)
	at cljs.repl.browser$browser_eval.invokeStatic(browser.clj:283)
	at cljs.repl.browser$browser_eval.invoke(browser.clj:272)
	at cljs.repl.browser.BrowserEnv._evaluate(browser.clj:373)
	at cljs.repl$evaluate_form.invokeStatic(repl.cljc:568)
	at cljs.repl$evaluate_form.invoke(repl.cljc:498)
	at cljs.repl$repl_STAR_.invokeStatic(repl.cljc:946)
	at cljs.repl$repl_STAR_.invoke(repl.cljc:855)
	at cljs.repl$repl.invokeStatic(repl.cljc:1100)
	at cljs.repl$repl.doInvoke(repl.cljc:1030)
	at clojure.lang.RestFn.invoke(RestFn.java:410)
	at user$eval2535.invokeStatic(NO_SOURCE_FILE:8)
	at user$eval2535.invoke(NO_SOURCE_FILE:8)
	at clojure.lang.Compiler.eval(Compiler.java:7062)
	at clojure.lang.Compiler.eval(Compiler.java:7025)
	at clojure.core$eval.invokeStatic(core.clj:3206)
	at clojure.core$eval.invoke(core.clj:3202)
	at clojure.main$repl$read_eval_print__8572$fn__8575.invoke(main.clj:243)
	at clojure.main$repl$read_eval_print__8572.invoke(main.clj:243)
	at clojure.main$repl$fn__8581.invoke(main.clj:261)
	at clojure.main$repl.invokeStatic(main.clj:261)
	at clojure.main$repl_opt.invokeStatic(main.clj:325)
	at clojure.main$main.invokeStatic(main.clj:424)
	at clojure.main$main.doInvoke(main.clj:387)
	at clojure.lang.RestFn.invoke(RestFn.java:397)
	at clojure.lang.AFn.applyToHelper(AFn.java:152)
	at clojure.lang.RestFn.applyTo(RestFn.java:132)
	at clojure.lang.Var.applyTo(Var.java:702)
	at clojure.main.main(main.java:37)

"VM Thread" os_prio=31 tid=0x00007ff1d1811000 nid=0x2d03 runnable

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007ff1d2010800 nid=0x1e07 runnable

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007ff1d2802800 nid=0x1d03 runnable

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007ff1d3006800 nid=0x2b03 runnable

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007ff1d2803000 nid=0x5403 runnable

"VM Periodic Task Thread" os_prio=31 tid=0x00007ff1d206b000 nid=0x3903 waiting on condition

JNI global references: 248

Activity

Hide
Timothy Pote added a comment - - edited

I think the issue here is a race condition around the connections in cljs.repl.server/connq. When it appears to work, this is the flow:

1) exit a cljs repl (via :cljs/quit)
2) connq still holds a ref to the now defunct conn
3) you start a new repl, which goes through setup
4) the browser makes its `:ready` request which calls (.clear connq)
5) repl initialization invokes its `init` fn (which evaluates a form using a conn in connq)

However, if 4 and 5 are switched (which can happen, since it depends on the timing of the browser's initial request), you’ll be given the defunct conn that is still in connq, causing you to hang indefinitely.

My question is: is there a reason we shouldn’t clear the connq in the browser repl tear-down?

Show
Timothy Pote added a comment - - edited I think the issue here is a race condition around the connections in cljs.repl.server/connq. When it appears to work, this is the flow: 1) exit a cljs repl (via :cljs/quit) 2) connq still holds a ref to the now defunct conn 3) you start a new repl, which goes through setup 4) the browser makes its `:ready` request which calls (.clear connq) 5) repl initialization invokes its `init` fn (which evaluates a form using a conn in connq) However, if 4 and 5 are switched (which can happen, since it depends on the timing of the browser's initial request), you’ll be given the defunct conn that is still in connq, causing you to hang indefinitely. My question is: is there a reason we shouldn’t clear the connq in the browser repl tear-down?

People

Vote (0)
Watch (0)

Dates

  • Created:
    Updated: