`[shadow-cljs]` output lost when repl-ing node http server

[harold]

Hi, thanks as ever for CIDER - we live inside it and it's amazing. I'm digging deeper into shadow-cljs and am getting hung up because my print output is getting lost in this one specific case...

Expected behavior

println produces output in the repl

Actual behavior

I cannot find my println output anywhere (:

Steps to reproduce the problem

When using shadow-cljs without CIDER, I eventually see the "INSIDE" printed:

$ npx create-cljs-project node-server-test
[snip...]
----
Done. Actual project initialization will follow soon.
----
$ cd node-server-test/
$ npx shadow-cljs node-repl
shadow-cljs - config: /home/harold/node-server-test/shadow-cljs.edn
shadow-cljs - updating dependencies
shadow-cljs - dependencies updated
shadow-cljs - server version: 2.26.2 running at http://localhost:9630
shadow-cljs - nREPL server started on port 36159
shadow-cljs - #4 ready!
cljs.user=> (defn handler [req res] (println "INSIDE") (.write res "Hello!") (.end res))
#'cljs.user/handler
cljs.user=> (require '["http" :as http])
nil
cljs.user=> (def s (http/createServer handler))
#'cljs.user/s
cljs.user=> (.listen s 8000)
#object[Server [object Object]]

;; Then, in another terminal:
$ curl localhost:8000
Hello!

;; And this is seen in the terminal repl:
cljs.user=> INSIDE

When doing the same thing in CIDER:

(cider-jack-in-cljs)
shadow
node-repl
;; Connected to nREPL server - nrepl://localhost:42703
;; CIDER 1.9.0 (Barcelona), nREPL 1.0.0
;; Clojure 1.11.1, Java 11.0.21
;;     Docs: (doc function-name)
;;           (find-doc part-of-name)
;;   Source: (source function-name)
;;  Javadoc: (javadoc java-object-or-class)
;;     Exit: <C-c C-q>
;;  Results: Stored in vars *1, *2, *3, an exception in *e;
;;  Startup: /usr/local/bin/npx shadow-cljs -d nrepl/nrepl:1.0.0 -d cider/cider-nrepl:0.41.0 -d cider/piggieback:0.5.3 server
;;
;; ClojureScript REPL type: shadow
;; ClojureScript REPL init form: (do (require '[shadow.cljs.devtools.api :as shadow]) (shadow/node-repl))
;;
To quit, type: :cljs/quit
[:selected :node-repl]
shadow.user> 
cljs.user> (defn handler [req res] (println "INSIDE") (.write res "Hello!") (.end res))
#'cljs.user/handler
cljs.user> (require '["http" :as http])
nil
cljs.user> (def s (http/createServer handler))
#'cljs.user/s
cljs.user> (.listen s 8000)
#object[Server [object Object]]
;; And now in the other terminal curl works works again (: 
;; but the "INSIDE" print output is never seen :|
cljs.user> 

Environment & Version information

Emacs version

27.1

Operating system

$ lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 22.04.1 LTS
Release:	22.04
Codename:	jammy

JDK distribution

$ java --version
openjdk 11.0.21 2023-10-17
OpenJDK Runtime Environment (build 11.0.21+9-post-Ubuntu-0ubuntu122.04)
OpenJDK 64-Bit Server VM (build 11.0.21+9-post-Ubuntu-0ubuntu122.04, mixed mode, sharing)

---

Thanks in advance for your time and consideration, I am looking forward to developing this node app inside cider with shadow-cljs. 😄

[vemv]

Thanks for a nice report!

I'll check it out as time allows.

You might have luck with logging in the meantime. It would also be interesting because Cider Log could eventually support it.

(right now it wouldn't, because only a few JVM logging backends are supported. But if you use a specific, popular choice for node.js, we'll have a motivation to keep things growing)

[harold]

Logging is a good idea, thanks for that. https://github.com/winstonjs/winston looks like a popular choice, so I'll investigate that.

Let me know if there's more I can do or provide to help figure out where the output is getting lost here.

Appreciate you very much.

[github-actions]

This issue has been automatically marked as stale because it has not had any recent activity. It will be closed soon if no further activity occurs. Thank you for your contribution and understanding!

[github-actions]

This issue been automatically closed due to lack of activity. Feel free to re-open it if you ever come back to it.

[harold]

Hi all, hope you're well. This problem still exists with the same symptoms. I am interested in fixing it, but don't really know where to start.

It's very interesting because (of course) println works great in the repl, except in these call chains inside the node http server in CIDER.

Not really sure what could cause this, because the prints work fine in plain node, and even the shadow-repl (without CIDER).

@alexander-yakushev - any thoughts here? Or can you point me in the right direction (coach me) to investigate this?

[harold]

I would like to Reopen the issue, but I am not allowed. (:

[harold]

Looked into this a bit tonight, here's the first clue.

When doing println in the repl (outside of the server handler), cider-repl--emit-output is called and putting (backtrace) in there shows where it's called from:

  backtrace()
  cider-repl--emit-output(#<buffer *cider-repl src/redacted:localhost:36471(cljs:shadow)*> "X\n" cider-repl-stdout-face)
  cider-repl-emit-stdout(#<buffer *cider-repl src/redacted:localhost:36471(cljs:shadow)*> "X\n")
  #<subr F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_40>(#<buffer *cider-repl src/redacted:localhost:36471(cljs:shadow)*> "X\n")
  #f(compiled-function (response) #<bytecode 0xebc7989e0c00107>)((dict "id" "124" "out" "X\n" "session" "77577347-fb53-4591-b4ce-32613c817972"))
  #f(compiled-function (response) #<bytecode 0x142a5033fef931ac>)((dict "id" "124" "out" "X\n" "session" "77577347-fb53-4591-b4ce-32613c817972"))
  nrepl--dispatch-response((dict "id" "124" "out" "X\n" "session" "77577347-fb53-4591-b4ce-32613c817972"))
  nrepl-client-filter(#<process nrepl-connection> "d2:id3:1243:out2:X\n7:session36:77577347-fb53-4591-...")

So, the output is originating in some nrepl response (which makes sense).

Now, inside the server handler, the call to println doesn't result in any call to cider-repl--emit-output. No nrepl messages are sent at all (I was running with nrepl-toggle-message-logging).

So, the next step is to figure out how output/streams from the underlying node process are meant to make it through to the repl. As shown in the original report, the println in the server handler does show up in the shadow-cljs command line node-repl, so it should be possible to capture somehow.

If anyone can point me to where the streams might get hooked up, that'd be great. Otherwise, that's what I'll be grepping around for when I have a chance to work on this next.

Thanks!

[harold]

Also, not sure if it's the same root cause, but this code also results in prints in npx shadow-cljs node-repl, but not in cider:

(js/setInterval #(println "Still alive @" (.toISOString (js/Date.))) 2000) 

[harold]

Potentially relevant?

cider/cider-connection.el

Lines 380 to 385 in d6a875b

	;; Redirect the nREPL's terminal output to a REPL buffer.
	;; If we don't do this the server's output will end up
	;; in the *nrepl-server* buffer.
	(when (and cider-redirect-server-output-to-repl
	(cider-nrepl-op-supported-p "out-subscribe"))
	(cider--subscribe-repl-to-server-out))

But maybe not... May need to investigate into the shadow nrepl server implementation to see what it's doing with the streams.

[github-actions]

This issue has been automatically marked as stale because it has not had any recent activity. It will be closed soon if no further activity occurs. Thank you for your contribution and understanding!