timeline/html: intermittent IllegalStateException: Can't set!: *current-length* from non-binding thread

[ttyusupov]

Noticed that sometimes timeline/html checker is failing with following stack trace:

2018-06-06 11:36:03,693{GMT}    WARN    [clojure-agent-send-off-pool-0] jepsen.checker: Error while checking history:
java.lang.IllegalStateException: Can't set!: *current-length* from non-binding thread
        at clojure.lang.Var.set(Var.java:220) ~[clojure-1.9.0.jar:na]
        at clojure.pprint$write_out.invokeStatic(pprint_base.clj:193) ~[clojure-1.9.0.jar:na]
        at clojure.pprint$pprint$fn__9743.invoke(pprint_base.clj:249) ~[clojure-1.9.0.jar:na]
        at clojure.pprint$pprint.invokeStatic(pprint_base.clj:248) ~[clojure-1.9.0.jar:na]
        at clojure.pprint$pprint.invoke(pprint_base.clj:241) ~[clojure-1.9.0.jar:na]
        at clojure.pprint$pprint.invokeStatic(pprint_base.clj:245) ~[clojure-1.9.0.jar:na]
        at clojure.pprint$pprint.invoke(pprint_base.clj:241) ~[clojure-1.9.0.jar:na]
        at jepsen.util$pprint_str.invokeStatic(util.clj:304) ~[jepsen-0.1.10-SNAPSHOT.jar:na]
        at jepsen.util$pprint_str.invoke(util.clj:303) ~[jepsen-0.1.10-SNAPSHOT.jar:na]
        at jepsen.checker.timeline$render_op.invokeStatic(timeline.clj:57) ~[classes/:na]
        at jepsen.checker.timeline$render_op.invoke(timeline.clj:57) ~[classes/:na]
        at jepsen.checker.timeline$title.invokeStatic(timeline.clj:85) ~[classes/:na]
        at jepsen.checker.timeline$title.invoke(timeline.clj:76) ~[classes/:na]
        at jepsen.checker.timeline$pair__GT_div.invokeStatic(timeline.clj:120) ~[classes/:na]
        at jepsen.checker.timeline$pair__GT_div.invoke(timeline.clj:97) ~[classes/:na]
        at clojure.core$partial$fn__5565.invoke(core.clj:2630) ~[clojure-1.9.0.jar:na]
        at clojure.core$map$fn__5587.invoke(core.clj:2747) ~[clojure-1.9.0.jar:na]
        at clojure.lang.LazySeq.sval(LazySeq.java:40) ~[clojure-1.9.0.jar:na]
        at clojure.lang.LazySeq.seq(LazySeq.java:49) ~[clojure-1.9.0.jar:na]
        at clojure.lang.RT.seq(RT.java:528) ~[clojure-1.9.0.jar:na]
        at clojure.core$seq__5124.invokeStatic(core.clj:137) ~[clojure-1.9.0.jar:na]
        at clojure.core$map$fn__5587.invoke(core.clj:2738) ~[clojure-1.9.0.jar:na]
        at clojure.lang.LazySeq.sval(LazySeq.java:40) ~[clojure-1.9.0.jar:na]
        at clojure.lang.LazySeq.seq(LazySeq.java:49) ~[clojure-1.9.0.jar:na]
        at clojure.lang.RT.seq(RT.java:528) ~[clojure-1.9.0.jar:na]
        at clojure.core$seq__5124.invokeStatic(core.clj:137) ~[clojure-1.9.0.jar:na]
        at clojure.core$apply.invokeStatic(core.clj:652) ~[clojure-1.9.0.jar:na]
        at clojure.core$apply.invoke(core.clj:652) ~[clojure-1.9.0.jar:na]
        at hiccup.compiler$fn__4842.invokeStatic(compiler.clj:88) ~[jepsen-0.1.10-SNAPSHOT.jar:na]
        at hiccup.compiler$fn__4842.invoke(compiler.clj:82) ~[jepsen-0.1.10-SNAPSHOT.jar:na]
        at hiccup.compiler$fn__4825$G__4820__4830.invoke(compiler.clj:68) ~[jepsen-0.1.10-SNAPSHOT.jar:na]
        at clojure.lang.Var.invoke(Var.java:381) ~[clojure-1.9.0.jar:na]
        at jepsen.checker.timeline$html$reify__492.check(timeline.clj:163) ~[na:na]
        at jepsen.checker$check_safe.invokeStatic(checker.clj:71) [jepsen-0.1.10-SNAPSHOT.jar:na]
        at jepsen.checker$check_safe.invoke(checker.clj:64) [jepsen-0.1.10-SNAPSHOT.jar:na]
        at jepsen.checker$compose$reify__3952$fn__3954.invoke(checker.clj:87) [jepsen-0.1.10-SNAPSHOT.jar:na]
        at clojure.core$pmap$fn__8105$fn__8106.invoke(core.clj:6942) [clojure-1.9.0.jar:na]
        at clojure.core$binding_conveyor_fn$fn__5476.invoke(core.clj:2022) [clojure-1.9.0.jar:na]
        at clojure.lang.AFn.call(AFn.java:18) [clojure-1.9.0.jar:na]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_131]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_131]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_131]
        at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]

I've tried to reproduce the issue in REPL using the same saved history file, but no luck - this way it works fine. Googled for Can't set!: ... from non-binding thread and it looks like this is a threading issue which might be related to usage of clojure.pprint in different threads?

[aphyr]

Never hit that one before, but pprint does a lot of weird stateful stuff with the stm. It's also real slow so maybe we should replace it with fipp or something faster.On Jun 15, 2018 04:51, Timur Yusupov [email protected] wrote:Noticed that sometimes timeline/html checker is failing with following stack trace: 2018-06-06 11:36:03,693{GMT} WARN [clojure-agent-send-off-pool-0] jepsen.checker: Error while checking history: java.lang.IllegalStateException: Can't set!: current-length from non-binding thread at clojure.lang.Var.set(Var.java:220) ~[clojure-1.9.0.jar:na] at clojure.pprint$write_out.invokeStatic(pprint_base.clj:193) ~[clojure-1.9.0.jar:na] at clojure.pprint$pprint$fn__9743.invoke(pprint_base.clj:249) ~[clojure-1.9.0.jar:na] at clojure.pprint$pprint.invokeStatic(pprint_base.clj:248) ~[clojure-1.9.0.jar:na] at clojure.pprint$pprint.invoke(pprint_base.clj:241) ~[clojure-1.9.0.jar:na] at clojure.pprint$pprint.invokeStatic(pprint_base.clj:245) ~[clojure-1.9.0.jar:na] at clojure.pprint$pprint.invoke(pprint_base.clj:241) ~[clojure-1.9.0.jar:na] at jepsen.util$pprint_str.invokeStatic(util.clj:304) ~[jepsen-0.1.10-SNAPSHOT.jar:na] at jepsen.util$pprint_str.invoke(util.clj:303) ~[jepsen-0.1.10-SNAPSHOT.jar:na] at jepsen.checker.timeline$render_op.invokeStatic(timeline.clj:57) ~[classes/:na] at jepsen.checker.timeline$render_op.invoke(timeline.clj:57) ~[classes/:na] at jepsen.checker.timeline$title.invokeStatic(timeline.clj:85) ~[classes/:na] at jepsen.checker.timeline$title.invoke(timeline.clj:76) ~[classes/:na] at jepsen.checker.timeline$pair__GT_div.invokeStatic(timeline.clj:120) ~[classes/:na] at jepsen.checker.timeline$pair__GT_div.invoke(timeline.clj:97) ~[classes/:na] at clojure.core$partial$fn__5565.invoke(core.clj:2630) ~[clojure-1.9.0.jar:na] at clojure.core$map$fn__5587.invoke(core.clj:2747) ~[clojure-1.9.0.jar:na] at clojure.lang.LazySeq.sval(LazySeq.java:40) ~[clojure-1.9.0.jar:na] at clojure.lang.LazySeq.seq(LazySeq.java:49) ~[clojure-1.9.0.jar:na] at clojure.lang.RT.seq(RT.java:528) ~[clojure-1.9.0.jar:na] at clojure.core$seq__5124.invokeStatic(core.clj:137) ~[clojure-1.9.0.jar:na] at clojure.core$map$fn__5587.invoke(core.clj:2738) ~[clojure-1.9.0.jar:na] at clojure.lang.LazySeq.sval(LazySeq.java:40) ~[clojure-1.9.0.jar:na] at clojure.lang.LazySeq.seq(LazySeq.java:49) ~[clojure-1.9.0.jar:na] at clojure.lang.RT.seq(RT.java:528) ~[clojure-1.9.0.jar:na] at clojure.core$seq__5124.invokeStatic(core.clj:137) ~[clojure-1.9.0.jar:na] at clojure.core$apply.invokeStatic(core.clj:652) ~[clojure-1.9.0.jar:na] at clojure.core$apply.invoke(core.clj:652) ~[clojure-1.9.0.jar:na] at hiccup.compiler$fn__4842.invokeStatic(compiler.clj:88) ~[jepsen-0.1.10-SNAPSHOT.jar:na] at hiccup.compiler$fn__4842.invoke(compiler.clj:82) ~[jepsen-0.1.10-SNAPSHOT.jar:na] at hiccup.compiler$fn__4825$G__4820__4830.invoke(compiler.clj:68) ~[jepsen-0.1.10-SNAPSHOT.jar:na] at clojure.lang.Var.invoke(Var.java:381) ~[clojure-1.9.0.jar:na] at jepsen.checker.timeline$html$reify__492.check(timeline.clj:163) ~[na:na] at jepsen.checker$check_safe.invokeStatic(checker.clj:71) [jepsen-0.1.10-SNAPSHOT.jar:na] at jepsen.checker$check_safe.invoke(checker.clj:64) [jepsen-0.1.10-SNAPSHOT.jar:na] at jepsen.checker$compose$reify__3952$fn__3954.invoke(checker.clj:87) [jepsen-0.1.10-SNAPSHOT.jar:na] at clojure.core$pmap$fn__8105$fn__8106.invoke(core.clj:6942) [clojure-1.9.0.jar:na] at clojure.core$binding_conveyor_fn$fn__5476.invoke(core.clj:2022) [clojure-1.9.0.jar:na] at clojure.lang.AFn.call(AFn.java:18) [clojure-1.9.0.jar:na] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_131] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]

I've tried to reproduce the issue in REPL using the same saved history file, but no luck - this way it works fine. Googled for Can't set!: ... from non-binding thread and it looks like this is a threading issue which might be related to usage of clojure.pprint in different threads?

—You are receiving this because you are subscribed to this thread.Reply to this email directly, view it on GitHub, or mute the thread.