prepl warnings remain buffered until explicit flushing from the client

Question

In a prepl session, Clojure warnings remain buffered and won't be sent to the client without flushing explicitly from the client side.

Here is an example prepl session using netcat (the lines starting with ;; indicate responses from the prepl server):

$ clojure -X clojure.core.server/start-server :name prepl :port 5555 :accept clojure.core.server/io-prepl :server-daemon false &
$ nc localhost 5555

(set! *warn-on-reflection* true)
;; {:tag :ret, :val "true", :ns "user", :ms 2, :form "(set! *warn-on-reflection* true)"}

(.toString (identity "foo"))
;; {:tag :ret, :val "\"foo\"", :ns "user", :ms 4, :form "(.toString (identity \"foo\"))"}
(binding [*out* *err*] (flush))
;; {:tag :err, :val "Reflection warning, NO_SOURCE_PATH:2:1 - reference to field toString can't be resolved.\n"}
;; {:tag :ret, :val "nil", :ns "user", :ms 4, :form "(binding [*out* *err*] (flush))"}

(defn identity [x] x)
;; {:tag :ret, :val "#'user/identity", :ns "user", :ms 3, :form "(defn identity [x] x)"}
(binding [*out* *err*] (flush))
;; {:tag :err, :val "WARNING: identity already refers to: #'clojure.core/identity in namespace: user, being replaced by: #'user/identity\n"}
;; {:tag :ret, :val "nil", :ns "user", :ms 2, :form "(binding [*out* *err*] (flush))"}

This seems to be caused by the fact that prepl's *err* PrintWriter is not autoFlush-enabled and that most of the Clojure warnings are not flushed explicitly.

Is this an issue to be addressed? Or is it an intended behavior and it's the client's responsibility to flush the error stream on a timely basis?

Answer 1

Here is a patch. I don't have another way to contribute this.

From 52fe3111bf0f8f769121bdc2c383a3f11aac695f Mon Sep 17 00:00:00 2001
From: Ray McDermott <ray.mcdermott@opengrail.com>
Date: Tue, 26 Apr 2022 21:52:21 +0200
Subject: [PATCH] Fix for #CLJ-2645

---
 src/clj/clojure/core/server.clj |  4 ++--
 src/clj/clojure/core_print.clj  | 41 ++++++++++++++++++---------------
 2 files changed, 24 insertions(+), 21 deletions(-)

diff --git a/src/clj/clojure/core/server.clj b/src/clj/clojure/core/server.clj
index 3cda4d1f74..c774cab3b5 100644
--- a/src/clj/clojure/core/server.clj
+++ b/src/clj/clojure/core/server.clj
@@ -220,8 +220,8 @@
     (m/with-bindings
       (in-ns 'user)
       (binding [*in* (or stdin in-reader)
-                *out* (PrintWriter-on #(out-fn {:tag :out :val %1}) nil)
-                *err* (PrintWriter-on #(out-fn {:tag :err :val %1}) nil)]
+                *out* (PrintWriter-on #(out-fn {:tag :out :val %1}) nil true)
+                *err* (PrintWriter-on #(out-fn {:tag :err :val %1}) nil true)]
         (try
           (add-tap tapfn)
           (loop []
diff --git a/src/clj/clojure/core_print.clj b/src/clj/clojure/core_print.clj
index 18c5101c1d..4f10b780a1 100644
--- a/src/clj/clojure/core_print.clj
+++ b/src/clj/clojure/core_print.clj
@@ -559,23 +559,26 @@
 (defn ^java.io.PrintWriter PrintWriter-on
   "implements java.io.PrintWriter given flush-fn, which will be called
   when .flush() is called, with a string built up since the last call to .flush().
-  if not nil, close-fn will be called with no arguments when .close is called"
+  if not nil, close-fn will be called with no arguments when .close is called.
+  autoflush? determines if the PrintWriter will autoflush, false by default."
   {:added "1.10"}
-  [flush-fn close-fn]
-  (let [sb (StringBuilder.)]
-    (-> (proxy [Writer] []
-          (flush []
-                 (when (pos? (.length sb))
-                   (flush-fn (.toString sb)))
-                 (.setLength sb 0))
-          (close []
-                 (.flush ^Writer this)
-                 (when close-fn (close-fn))
-                 nil)
-          (write [str-cbuf off len]
-                 (when (pos? len)
-                   (if (instance? String str-cbuf)
-                     (.append sb ^String str-cbuf ^int off ^int len)
-                     (.append sb ^chars str-cbuf ^int off ^int len)))))
-        java.io.BufferedWriter.
-        java.io.PrintWriter.)))
+  ([flush-fn close-fn]
+   (PrintWriter-on flush-fn close-fn false))
+  ([flush-fn close-fn autoflush?]
+   (let [sb (StringBuilder.)]
+     (-> (proxy [Writer] []
+           (flush []
+             (when (pos? (.length sb))
+               (flush-fn (.toString sb)))
+             (.setLength sb 0))
+           (close []
+             (.flush ^Writer this)
+             (when close-fn (close-fn))
+             nil)
+           (write [str-cbuf off len]
+             (when (pos? len)
+               (if (instance? String str-cbuf)
+                 (.append sb ^String str-cbuf ^int off ^int len)
+                 (.append sb ^chars str-cbuf ^int off ^int len)))))
+         java.io.BufferedWriter.
+         (java.io.PrintWriter. ^boolean autoflush?)))))

Comments

Added to the JIRA issue

---

We've added this to the 1.12 Candidates list and will circle back on it ASAP. Thanks for your contribution!

---

Thank you for the encouragement :)

Answer 2

This issue seems to have been filed to JIRA as CLJ-2645.

Answer 3

We recently discussed this on the Clojurian Slack and @alex asked for follow up here.

The problem with the client doing a flush is that messages will appear out of order.

The requirement for flushing is not documented - although it could be.

However, in the case of io-prepl which is a prepl client maintained in the same ns, the io-prepl or its clients cannot force flushes so the error messages are lost.

The prepl docstring says that there will be exactly one :ret.

I have assumed that execution is complete once a :ret tag is received. I'm not sure how else a prepl client program is meant to understand the completion of the execution.

The code suggests that it is intended to be the last message but I understand that it's subject to change. In any case, some signal of completion is required if it isn't that one.

Slack user @flowthing proposed a fix to the prepl along the lines you show above.

(when-not (= :repl/quit ret)
  (set! *3 *2)

Is replaced with:

(when-not (= :repl/quit ret)
  (binding [*out* *err*] (flush)) ; this is the only difference to the original
  (set! *3 *2)

This is a simple fix and ensures that all prepl clients receive errors in a timely fashion and in correct order (ie before :ret).

Without this fix in core, I have had to fork the prepl and io-prepl as there is no other obvious way around this from external code.

Answer 4

The fundamental problem here is that *err* is not flushed in a controlled manner.

For the sake of completion, another possibility floated by Slack user @flowthing was to add an option to PrintWriter-on, or another PrintWriter wrapper, to make the underlying Writer auto-flush.

This would also work since the prepl binds out and err to PrintWriter-ons.

Clients must pass an outfn to the prepl and the function passed by io-prepl binds *flush-on-newline* to true which is respected by prn - called on every value.

Calls to prn thus ensure that out is always flushed.

A similar mechanism to prn for *err* that observed *flush-on-newline* could also provide the parts needed for a solution.

Comments

After comparing both options and making some tests, adding an autoflush option to `PrinteWriter-on` via a new arity works well and feels like a cleaner solution.

I don't want to also fork a core function though so I 'll stick with the `binding` hack for now.

I would be happy to supply a patch if I get some encouragement.

---

Go Ray Go! You can do this! :)

---

Did not expect that. OK!

---

Patch is done. I have signed the CCA back in the day but don't have a JIRA account