Clojurians Log v2

Checking the gist mentioned here: https://clojurians.slack.com/archives/C17JYSA3H/p1683740101983519?thread_ts=1683660740.358509&cid=C17JYSA3H If I evaluate this in the REPL, it fixes the issue:

(import 'org.apache.commons.io.output.WriterOutputStream)
  (import 'java.io.PrintStream)
  (System/setOut (PrintStream. (WriterOutputStream. *out*) true))
  (alter-var-root #'*out* (fn [_] *out*))

fwiw you should be able to repro this with simply ‘future’

from RCF github: (sorry on mobile) (tests (future (tap 1) (Thread/sleep 10) ; tap value to queue (tap 2) (Thread/sleep 200) (tap 3)) % := 1 ; pop queue % := 2 % := rcf/timeout)

I’ve now added a workaround that seems to work to the Calva issue tracking this: https://github.com/BetterThanTomorrow/calva/issues/2300#issuecomment-1697354243

how can i help test

oh i see, the custom connect sequence

It’s not that, actually. But similar. I added a side effect of the workaround as a comment there now. It might interest you in particular, @dustingetz. 😃

Why do you want them separated? It makes sense to me that all output route to the REPL

departure from that behavior used to confuse me a lot

Maybe this answers my question if this is what CIDER is doing. From the nrepl messages log I pasted here, it looks like in cider the messages come in with the same message id as the evaluation. Unlike with Calva, where the out-of-band messages come in with some old message id.

As I mentioned in that Calva thread, I like that shadow-cljs output that is not a result of something I do in the repl, does not show up in the repl output. I like that it is kept separate. I usually run with shadow-cljs tests set to auto-run, so they are run when I save a file. That prints the test results in the jack-in terminal and not in my repl output. Now, the stdout coming from things like the future code you provided, is a result of something I do in the REPL, so it confuses me to no end that it turns up somewhere else than in the repl output… But the workaround I have so far, does not allow Calva to separate it. If I can separate it, I can consolidate it, and you would be able to choose that experience (given that we deem it something worth to maintain a setting for). Not being able to separate it limits the options. Does that make sense?

BTW. I’m actually not clear about how to reproduce the problem using future.

my mistake, Future is conveying bindings, or attempting to, IIRC clojure has tech debt here I need to find my notes

(comment "println from second thread with future"
  (do (println "hello") (future (println "world")))
  ; hello
  ; world
  ; #<Future@403ac18d: nil>
  )

(comment "println from second thread with java Thread constructor"
  (do (println "hello")
    (doto (java.lang.Thread. #(println "world")) (.start)))
  ; hello
  ; #object[java.lang.Thread 0x1952f3ce "Thread[Thread-43,5,main]"] 
  )

(comment
  "bypass Clojure *out* binding"
  (.println System/out "Hello stdout.")
  ; nil
  )

Merely running (alter-var-root #'*out* (fn [_] *out*)) is sufficient to "fix" cases #1 and #2

(clojure.tools.logging/info "asd")

Shadow has a https://github.com/thheller/shadow-cljs/blob/dbcd04a0bc0dfb6b69230c5ce1e168442a7bb997/src/main/shadow/jvm_log.clj#L46, maybe you can intercept shadow only with a custom shadow logger? (That would be an opt-in thing for your local preference)

(shadow.jvm-log/info ::foo "hi") logs to java stdout by default, bypassing *out* [2023-08-29 10:35:34.138 - INFO] :missionary-docs.missionary-examples/foo - "hi"

however shadow deliberately sends user-facing error reports to *out* https://github.com/thheller/shadow-cljs/blob/dbcd04a0bc0dfb6b69230c5ce1e168442a7bb997/src/main/shadow/cljs/devtools/server/util.clj#L156 with println

actually it's redirecting out to err

This Calva build fixes the problem the same way as CIDER does it. https://output.circle-artifacts.com/output/job/bdd60eab-29e7-4072-ba2d-3f4c2248160d/artifacts/0/tmp/artifacts/calva-2.0.388-2300-subscribe-stdout-5c1ed69b.vsix (Next build will make it possible to opt out.)

Consider this missionary code:

(def nap (m/sleep 1000))
  (def slowmo-hello-world
    (m/sp (println "Hello")
          (m/? nap)
          (println "World")
          (m/? nap)
          (println "!")))
  (let [begin (System/currentTimeMillis)]
    (m/? slowmo-hello-world)
    (println "Took: " (- (System/currentTimeMillis) begin) " ms"))

(-->
  id                             "24"
  op                             "eval"
  session                        "18dc8a24-8a63-44a6-bc04-bfd0d7bcd462"
  time-stamp                     "2023-08-28 09:58:13.762899000"
  code                           "(let [begin (System/currentTimeMillis)]
    (m/? slowmo-hell..."
  column                         3
  file                           "/Users/pez/Projects/tuts/missionary/src/walkthrough/task_flo..."
  line                           55
  nrepl.middleware.print/print   "cider.nrepl.pprint/pr"
  nrepl.middleware.print/quota   1048576
  nrepl.middleware.print/stream? nil
  ns                             "walkthrough.task-flows"
)
(<--
  id         "24"
  session    "18dc8a24-8a63-44a6-bc04-bfd0d7bcd462"
  time-stamp "2023-08-28 09:58:13.779922000"
  out        "Hello
"
)
(<--
  id         "24"
  session    "18dc8a24-8a63-44a6-bc04-bfd0d7bcd462"
  time-stamp "2023-08-28 09:58:14.785926000"
  out        "World
"
)
(<--
  id         "24"
  session    "18dc8a24-8a63-44a6-bc04-bfd0d7bcd462"
  time-stamp "2023-08-28 09:58:15.792402000"
  out        "!
"
)
(<--
  id         "24"
  session    "18dc8a24-8a63-44a6-bc04-bfd0d7bcd462"
  time-stamp "2023-08-28 09:58:15.793357000"
  out        "Took:  2014  ms
"
)
(<--
  id         "24"
  session    "18dc8a24-8a63-44a6-bc04-bfd0d7bcd462"
  time-stamp "2023-08-28 09:58:15.810448000"
  ns         "walkthrough.task-flows"
  value      "nil"
)
(<--
  id         "24"
  session    "18dc8a24-8a63-44a6-bc04-bfd0d7bcd462"
  time-stamp "2023-08-28 09:58:15.811493000"
  status     ("done")
)
(<--
  id                 "24"
  session            "18dc8a24-8a63-44a6-bc04-bfd0d7bcd462"
  time-stamp         "2023-08-28 09:58:15.811877000"
  changed-namespaces (dict)
  repl-type          "clj"
  status             ("state")
)

-> sent
{
  id: '116',
  op: 'eval',
  session: 'dc984898-6348-4259-a860-1c00008a7833',
  code: '(let [begin (System/currentTimeMillis)]\n' +
    '    (m/? slowmo-hello-world)\n' +
    '    (println "Took: " (- (System/currentTimeMillis) begin) " ms"))',
  file: '/Users/pez/Projects/tuts/missionary/src/walkthrough/task_flows.clj',
  line: 55,
  column: 3,
  stdout: [Function: stdout],
  stderr: [Function: stderr],
  pprint: false
}

<- received
{
  id: '116',
  out: 'Hello\n',
  session: 'dc984898-6348-4259-a860-1c00008a7833'
}

-> sent
{
  op: 'debug-instrumented-defs',
  id: '117',
  session: 'dc984898-6348-4259-a860-1c00008a7833'
}

<- received
{
  id: '117',
  list: [],
  session: 'dc984898-6348-4259-a860-1c00008a7833',
  status: [ 'done' ]
}

<- received
{
  id: '116',
  out: 'Took:  2008  ms\n',
  session: 'dc984898-6348-4259-a860-1c00008a7833'
}

<- received
{
  id: '116',
  ns: 'walkthrough.task-flows',
  session: 'dc984898-6348-4259-a860-1c00008a7833',
  value: 'nil'
}

<- received
{
  id: '116',
  session: 'dc984898-6348-4259-a860-1c00008a7833',
  status: [ 'done' ]
}

-> sent
{
  op: 'debug-instrumented-defs',
  id: '118',
  session: 'dc984898-6348-4259-a860-1c00008a7833'
}

<- received
{
  'changed-namespaces': {},
  id: '116',
  'repl-type': 'clj',
  session: 'dc984898-6348-4259-a860-1c00008a7833',
  status: [ 'state' ]
}

Regardless if I evaluate this from CIDER or Calva, this is printed in the terminal where the repl is started:

World
!

I guess this tells me that I need to check how Calva’s nrepl client is wired… CIDER clearly gets the messages, so they are sent…

No idea what’s going on. Now looked a bit deeper, and I don’t even see the messages coming in on the socket. Anyone knows if CIDER is doing something with the nrepl server when connecting to it, that would make it able to catch the stdout printed off the main thread and send it to the client?