Open mrrodriguez opened 6 years ago
@mrrodriguez I suspect this only happens when cold-compiling a codebase that already has spy statements in it, can you confirm?
@vvvvalvalval The app can be running and then hot-reloaded and still have this problem. However, I think I have to do a page refresh for this bad cljs to be generated via the logger crossing into the same output stream.
If I add a
[sc.api]
to a ns
:require
that already exists, put a (sc.api/spy :foo)
anywhere, and let figwheel hot-reload - with no manual page refresh, I instead get a
"Could not analyze"
java.lang.NullPointerException: at line <line where I have the `sc.api/spy` call.
So either way, it won't work with a lein + figwheel setup.
My leiningen
version is
Leiningen 2.8.1 on Java 1.8.0_112 Java HotSpot(TM) 64-Bit Server VM
and using Figwheel
[lein-figwheel "0.5.16"]
[figwheel-sidecar "0.5.16"]
The NPE from the analyzer is pretty hard to troubleshoot. I tried for a few hours one day and failed. I have to figure out how to recreate it with the Figwheel REPL analyzer pass and then walk through that.
If I'm in a Figwheel CLJS (via piggieback) REPL, I have tried
(require 'sc.api)
;;= nil
sc.api/spy
;;= #object[sc$api$spy]
Both of those work.
However, if I then do
(sc.api/spy :foo)
;; throws an error
---- Could not Analyze <cljs form> line:1 column:1 ----
at line 1 <cljs repl>
1 (sc.api/spy :foo)
^---
---- Analysis Error ----
nil
Interestingly I can do:
(#'sc.api/spy nil nil :foo)
;;= returns the macroexpanded form
I'm not sure if the NPE problem, analysis error, and the problem with the logger printing to the same out stream as the cljs compiler are all related. All of these issues have been hard to troubleshoot so far.
This is actually happening to me in 2 separate CLJS projects too, so it isn't just something completely unique to one codebase. However, the lein + figwheel stack is the same. I've tried different recent versions of figwheel, and that doesn't change anything.
I've read the relevant chunks of the scope-capture
codebase, and I don't see what would be wrong still though.
I am also having this same issue, with the same figwheel and lein versions that @mrrodriguez is using.
Any progress on this? Debugging the analyzer is a bit beyond my abilities, but happy to help with evidence collection etc.
@nickstares yes I'd need a precise repro to make progress please - a minimal project reproducing the problem with the exact dependencies would be ideal.
@vvvvalvalval I may try to get a reproducing case again today. I've had a hard time doing so before. When I make a small, dummy project, with a bunch of the same core dev dependencies, it hasn't happened. I have 2 "real" separate projects though, where it happens the same in each. I've been completely unable to use scope-capture
in my CLJS-side due to that.
So since it doesn't happen easily in a repro-case, the problem becomes trying to have a clue what is happening in the analyzer to try to recreate it...
Hopefully I can figure something out. I know there isn't much for you to go on from this issue so far.
I can reproduce this using figwheel template.
Once the app is up and running with cider and figwheel, All I have to do is add (sc.api/spy)
to core.cljs, save the file, and figwheel will throw the error on reload.
I do notice that this doesn't happen when using only lein figwheel
(without cider). So maybe it is an issue with figwheel-sidecar or piggieback?
See more info below.
I created the project with:
lein new figwheel scope-capture-demo
@vvvvalvalval @nickstares I was able to recreate it in a similar way and agree that the problem only seems to be with the figwheel-sidecare
+ piggieback
+ cider
setup.
~I'm thinking cider
doesn't matter, it's the other 2 involved. So will see about being able to narrow it down more.~
EDIT:
I looked a bit more at this and now I'm actually suspicious of cider
nrepl middleware. It is in the stacktrace posted above, but I'll show the relevant lines
Caused by: java.lang.NullPointerException
at clojure.core$deref_future.invokeStatic(core.clj:2292)
at clojure.core$deref.invokeStatic(core.clj:2312)
at clojure.core$deref.invoke(core.clj:2298)
at cider.nrepl.middleware.out$print_stream$fn__27410.invoke(out.clj:85)
at cider.nrepl.middleware.out.proxy$java.io.OutputStream$ff19274a.write(Unknown Source)
at java.io.PrintStream.write(PrintStream.java:480)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
at java.io.PrintStream.write(PrintStream.java:527)
at java.io.PrintStream.print(PrintStream.java:669)
at java.io.PrintStream.println(PrintStream.java:806)
at sc.api.logging$portable_println.invokeStatic(logging.cljc:17)
at sc.api.logging$portable_println.invoke(logging.cljc:15)
sc.api.logging/portable-println
is being called on the :clj
side. It looks like there may be interference with the cider.nrepl.middleware.out/print-stream
middleware.
Looking at the relevant Cider code:
(defn print-stream
"Returns a PrintStream suitable for binding as java.lang.System/out
or java.lang.System/err. All operations are forwarded to all output
bindings in the sessions of messages.
type is either :out or :err."
[type]
(let [printer (case type
:out '*out*
:err '*err*)]
(PrintStream. (proxy [OutputStream] []
(close [] (.flush ^OutputStream this))
(write
([int-or-bytes]
(.write @(resolve printer)
(if (instance? Integer int-or-bytes)
int-or-bytes
(String. int-or-bytes))))
([bytes ^Integer off ^Integer len]
(let [byte-range (byte-array
(take len (drop off bytes)))]
(.write @(resolve printer) (String. byte-range))))) <--- ERROR HAPPENS HERE
(flush []
(.flush @(resolve printer))))
true)))
It looks like the call to (resolve printer)
returns nil
. I believe that this is (resolve *out*)
.
I believe the reason it returns nil
is probably because the ns
bound is cljs.user
and resolution of things may be a bit different.
EDIT (2):
I played around with this and I'm now convinced the cider-nrepl
middleware above is the problem. In general, I think it is a tricky/error-prone situation in CLJS to have macros that try to resolve
vars at macroexpansion time, at least with figwheel reloading I believe.
So the function sc.api.logging/portable-println
was introduced in https://github.com/vvvvalvalval/scope-capture/commit/f7a58597e5fdf85a7aaa9465ff2e2455eec66567 to try deal with where the macroexpansion time code sites were logged to.
This works in basic cases because the reference is (.println System/out ^String s)
. However, with cider-nrepl
with-out
middleware enabled, System/out
is apparently masked behind a proxy. That proxy does a (resolve *out*)
, which can end up happening during CLJS analysis macroexpansion time. This breaks with a NPE.
A workaround for this issue is to put something like this:
(sc.api.logging/register-cs-logger
:sc.api.logging/log-spy-cs
(fn [cs]
nil))
NOTE: This is really the same workaround (in concept) that was around prior to sc.api.logging/portable-println
being added I believe, see #1 . The way there also should work for the same reasons.
In your user.clj
or somewhere you know will get loaded after sc.api
and before the CLJS compilation.
With this, there is no initial code site details logged anywhere. However, when execution points are logged later, they are logged at runtime to the CLJS out stream you'd expect, so you can still find where the execution points are to effectively use scope-capture
.
So now the question is, could/should scope-capture
try to do the initial macroexpansion-time code site logging in a way that is more robust to something like this middleware?
The cljs compiler uses *out*
for emitting strings. If you instead defaulted to *err*
, then it wouldn't conflict.
I still get logger output interleaved with the JS output that was discussed in #1 when using
[vvvvalvalval/scope-capture "0.2.0"]
in ClojureScript with Leiningen/cljs-build/figwheel setup.This problem seems to come and go from project to project or release to release of
scope-capture
for me. I haven't been able to narrow it down to a basic new project to reproduce it. I think it may be something with the combination of the tools involved.I'll add that I used to be able to use
scope-capture
with this same setup around the 2nd release. I am not sure I have enough details to be actionable here. I'm curious if anyone else is facing similar.