Clojurians Log v2

Here's a log from a test with nrepl master. It looks like the println output never gets sent from printing-transport. I see it in the terminal where I started the repl. (I am pretty sure I saw a different pattern yesterday, but I had been staring at this for very long then and might have been hallucinating.) I'll try with 0.6.0, since Calva behaves much better with master.

@pez Everything seems fine here. I don’t see any errors/problems.

> nrc receiving: {“id”:“39",“ns”:“live-hacking”,“printed-value”:1,“session”:“c9e4bd22-bdef-425f-9fb9-c4ef24aaaa3f”,“value”:“nil”}

I guess that’s the missing output you referred to, so that’s fine as well.

> I’ll try with 0.6.0, since Calva behaves much better with master.

I wonder why - there has been no changes other than the inclusion of the EDN transport and a bit of transport cleanup related to it. I can always cut some release for you, but I don’t think there should be any material differences.

No cutting of any releases yet. 😃 Things are not as they should with Calva, and I need to find and fix that.

> nrc receiving: {“id”:“39",“ns”:“live-hacking”,“printed-value”:1,“session”:“c9e4bd22-bdef-425f-9fb9-c4ef24aaaa3f”,“value”:“nil”} That's from the :cljs/quit, right?

My bad.

nrc sending: {"op":"eval","session":"c9e4bd22-bdef-425f-9fb9-c4ef24aaaa3f","code":"(println 1)","id":"38"}
nrc receiving: {"id":"38","ns":"cljs.user","printed-value":1,"session":"c9e4bd22-bdef-425f-9fb9-c4ef24aaaa3f","value":"nil"}

I pasted the wrong line. Looking at this it’s perfectly correct.

Your client logging seems a bit buggy, though. Notice:

nrc sending: {"op":"eval","session":"c9e4bd22-bdef-425f-9fb9-c4ef24aaaa3f","code":"(+ 1 1)","id":"37"}
nrc receiving: {"id":"37","ns":"cljs.user","printed-value":1,"session":"c9e4bd22-bdef-425f-9fb9-c4ef24aaaa3f","value":"2"}

You’ve got some printed-value here, although there should be none. Only value.

I have noticed that as well. But it is what I am logging from printing-transport as well:

printing-transport: {:id "37", :session "c9e4bd22-bdef-425f-9fb9-c4ef24aaaa3f", :value "2", :printed-value 1, :ns cljs.user}

Also. I think I must be missing something fundamental here. In my test script, and with 0.5.3, I get an out message, containing the output. I don't get that in these tests.

Hmm, I just assumed you had renamed out to printed-value in your logger.

Yeah, than something is broken indeed, but keep in mind there’s no printed-value field in nREPL at all.

Yeah, a bit confusing that I print 1. I've changed that now in my tests.

What’s the cider-nrepl you’re using, btw?

I have never relied on printed-value in any way. Been thinking I should ask about it, but now I know to continue disregard it.

0.21.1

Good.

And the out is missing only for ClojureScript, right?

Another thing I think is a bit off is:

nrc sending: {"op":"eval","session":"418d21f5-8cc5-47b4-a51c-be817ab10a00","code":"(println \"hello\")","id":"16"}
nrc receiving: {"id":"16","ns":"cljs.user","printed-value":1,"session":"418d21f5-8cc5-47b4-a51c-be817ab10a00","value":"nil"}
nrc receiving: {"id":"16","session":"418d21f5-8cc5-47b4-a51c-be817ab10a00","status":["done"]}

printing-transport: {:id "16", :session "418d21f5-8cc5-47b4-a51c-be817ab10a00", :value "nil", :printed-value 1, :ns cljs.user}
printing-transport: {:id "16", :session "418d21f5-8cc5-47b4-a51c-be817ab10a00", :status #{:done}}
printing-transport: {:id "16", :session "418d21f5-8cc5-47b4-a51c-be817ab10a00", :changed-namespaces {}, :repl-type :cljs, :status #{:state}}

Yes, only for ClojureScript.

(The reason my client doesn't log the state there is that I stop listening once I have gotten the done.)

But maybe I should be alert on : changed-namespaces... I notice that my repl prompt is sometimes lying...

With these tests, I get the same behaviour in 0.6.0 as in master, just as you expected, btw.

> But maybe I should be alert on : changed-namespaces... I notice that my repl prompt is sometimes lying...

You can safely ignore this. This middleware is in cider-nrepl and it tracks updates to namespaces, so the client to can act efficiently on them.

Most notably it provides you an up-to-date list of vars in the namespace so you can syntax highlight them accordingly.

We also use this in CIDER to show notifications that that source code and the REPL are in sync (meaning everything has been evaluated).

I'll implement that stuff once I've gotten this crazy println thing under control. 😃

Probably we should add some way for the middleware to be disabled without having to be removed from the middleware graph, for clients that don’t need it.

In generates a lot of messages which are confusing if someone doesn’t need it.

Huge messages, even. 😃

When I evaluate in a project that uses Figwheel Main and using the clojars 0.6.0, I get this when evaluating a printn:

nrc sending: {"op":"eval","session":"b282a095-a368-4ffd-9fc3-dec8549cbc2d","code":"(println \"Hello from CLJS\")","id":"16"}
nrc receiving: {"ex":"class java.lang.IllegalArgumentException","id":"16","root-ex":"class java.lang.IllegalArgumentException","session":"b282a095-a368-4ffd-9fc3-dec8549cbc2d","status":["eval-error"]} 

And also a stack trace in the terminal where I started the REPL.

You also have figwheel-sidecar there, right?

Yes

I now tested a thing and I think the exeception only comes if I have done (enable-console-print!). So that's one mystery less, hopefully.

:thumbsup:

Damnit. It wasn't (enable-console-print).

Now I have brought in Figwheel into the mix. Starting the nrepl project like so:

lein update-in :dependencies conj "[com.bhauman/figwheel-main \"0.2.0\"]" -- update-in :dependencies conj "[nrepl \"0.6.0-PEZ-TESTING\"]" -- update-in :dependencies conj "[cider/piggieback \"0.4.0\"]" -- update-in :dependencies conj "[figwheel-sidecar \"0.5.18\"]" -- update-in :plugins conj "[cider/cider-nrepl \"0.21.1\"]" -- update-in "[:repl-options :nrepl-middleware]" conj "[\"cider.nrepl/cider-middleware\"]" -- update-in "[:repl-options :nrepl-middleware]" conj "[\"cider.piggieback/wrap-cljs-repl\"]" -- with-profile fig repl

I don't get that when I evaluate inline in the buffer, however. Then my printing-transport logger writes this:

printing-transport: {:id "72", :session "41106734-a7e2-4b75-8509-d4a44f545601", :status #{:done}}
printing-transport: {:id 8, :session 41106734-a7e2-4b75-8509-d4a44f545601, :out hello
}
printing-transport: {:id "73", :session "41106734-a7e2-4b75-8509-d4a44f545601", :value "nil", :printed-value 1, :ns clojure.live-cljs-hacking}
printing-transport: {:id "73", :session "41106734-a7e2-4b75-8509-d4a44f545601", :status #{:done}}
printing-transport: {:id "74", :session "41106734-a7e2-4b75-8509-d4a44f545601", "file" nil, "line" 1, "ns" "clojure.live-cljs-hacking", "doc" nil, "name" "clojure.live-cljs-hacking", :status #{:done}}

I don't know why the two different methods to evaluate would give different results. Maybe it is because the buffer's session is cloned off early in the connection process, while the repl window's session is cloned later and something wedges itself in between those two clonings...

Now I must rest my brain from this a while. If someone has an idea about what else to investigate, please let me know.

Yet another thing that is funny is that the logged row with id 8 there is that both the id and the out are printed without quotes. Also If I alter the evaluated string, say to (println "hello again"), that is also logged with the same id, a bare 8.

Not sure that made sense. This is how the logs look.