Say the whole line, keep the credential out of it, and give Flutter a voice
Three things learned the hard way while chasing a reply chip, all of them about being able to see anything at all. The desktop's `FRQ_TRACE` printed the first hundred characters of a line. Tags come first and a signature is long enough to push every other tag past that cut, so the truncated form could not answer what a `+reply` said — or whether there was one — which is the only question the trace exists for. It prints the line now. Except an `AUTHENTICATE` payload, which is the credential itself: a trace is something you paste into a bug report, and the old one wrote a session token into /tmp in the clear. The Flutter half had no voice at all on a desktop. `print` is `cljd.core/print` writing to a `*out*` nothing is holding in a compiled bundle, and `dart:developer` — what `frq.net.dart` uses — goes to the VM service, not to the process's output, so `just flutter-desktop` shows neither. The comment there claimed otherwise; it says what is true now, and what to do instead. Three guesses were spent on that silence before a file proved the code had been running the whole time. `frq.debug` is that file, made reusable. `FRQ_JOT` names a path and `jot!` appends to it; off, it costs a deref. It never throws, because a diagnostic that takes the app down is worse than no diagnostic, and it appends rather than truncates, because the interesting run is usually the one after the one that told you where to look. The wire log goes through it, which is both what makes the namespace compile — ClojureDart builds what `frq.main` reaches, and nothing else — and the first thing anyone will want out of it. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
63365cd parent: 2abafda added
flutter/src/frq/debug.cljd +54 -0 | new file mode 100644 | ||
| @@ -0,0 +1,54 @@ | ||
| 1 | +(ns frq.debug | |
| 2 | + "A line of diagnostics from a running Flutter build, to a file. | |
| 3 | + | |
| 4 | + Nothing else here reaches you. `print` is `cljd.core/print` and writes to | |
| 5 | + `*out*`, which is nowhere at all in a compiled bundle; `dart:developer`'s | |
| 6 | + `log` — what `frq.net.dart` uses, and what its comment claims reaches a | |
| 7 | + terminal under `just flutter-desktop` — goes to the VM service, so it too | |
| 8 | + is silent when the bundle is launched directly, which is what that recipe | |
| 9 | + does. Both were tried first, and both looked exactly like the code never | |
| 10 | + running. A file is the one sink that cannot be swallowed by whoever is | |
| 11 | + holding stdout. | |
| 12 | + | |
| 13 | + Off unless `FRQ_JOT` names a path, so a `jot!` left in a hot build path | |
| 14 | + costs one `getenv`-backed deref and nothing else. The file is appended to | |
| 15 | + rather than truncated: the interesting run is usually the one after the one | |
| 16 | + that told you what to look at. | |
| 17 | + | |
| 18 | + FRQ_JOT=/tmp/frq-jump.log just flutter-desktop run | |
| 19 | + | |
| 20 | + Written for a jump that fired, scrolled, and was silently undone in the same | |
| 21 | + frame — see `frq.hiccup/end-ward!`. What settled it was not one line but the | |
| 22 | + order of several from different callbacks, which is the shape of question | |
| 23 | + this answers well: who ran, in what order, with what numbers. A debugger | |
| 24 | + cannot ask it, because stopping the app is what makes the frame stop being | |
| 25 | + a frame." | |
| 26 | + (:require ["dart:io" :as io])) | |
| 27 | + | |
| 28 | +(defonce ^:private sink | |
| 29 | + ;; Read once. An env var does not change under a running app, and this is | |
| 30 | + ;; called from inside build and post-frame callbacks. | |
| 31 | + (delay (let [p (get (.-environment io/Platform) "FRQ_JOT")] | |
| 32 | + (when (and p (seq p)) p)))) | |
| 33 | + | |
| 34 | +(defn on? | |
| 35 | + "Whether anything is listening, for a caller with expensive diagnostics to | |
| 36 | + build. `jot!` asks this itself; this is for the `(when (debug/on?) ...)` | |
| 37 | + around a string that costs something to make." | |
| 38 | + [] | |
| 39 | + (some? @sink)) | |
| 40 | + | |
| 41 | +(defn jot! | |
| 42 | + "Append one line, when `FRQ_JOT` named a file. Answers nil either way. | |
| 43 | + | |
| 44 | + Never throws: a diagnostic that takes the app down with it is worse than no | |
| 45 | + diagnostic, and the path may be unwritable for reasons that have nothing to | |
| 46 | + do with what is being looked at." | |
| 47 | + [& parts] | |
| 48 | + (when-let [path @sink] | |
| 49 | + (try | |
| 50 | + (.writeAsStringSync (io/File. path) | |
| 51 | + (str (apply str parts) "\n") | |
| 52 | + .mode io/FileMode.append) | |
| 53 | + (catch Exception _ nil))) | |
| 54 | + nil) | |
| new file mode 100644 | |||
| @@ -0,0 +1,54 @@ | |||
| 1 | +(ns frq.debug | ||
| 2 | + "A line of diagnostics from a running Flutter build, to a file. | ||
| 3 | + | ||
| 4 | + Nothing else here reaches you. `print` is `cljd.core/print` and writes to | ||
| 5 | + `*out*`, which is nowhere at all in a compiled bundle; `dart:developer`'s | ||
| 6 | + `log` — what `frq.net.dart` uses, and what its comment claims reaches a | ||
| 7 | + terminal under `just flutter-desktop` — goes to the VM service, so it too | ||
| 8 | + is silent when the bundle is launched directly, which is what that recipe | ||
| 9 | + does. Both were tried first, and both looked exactly like the code never | ||
| 10 | + running. A file is the one sink that cannot be swallowed by whoever is | ||
| 11 | + holding stdout. | ||
| 12 | + | ||
| 13 | + Off unless `FRQ_JOT` names a path, so a `jot!` left in a hot build path | ||
| 14 | + costs one `getenv`-backed deref and nothing else. The file is appended to | ||
| 15 | + rather than truncated: the interesting run is usually the one after the one | ||
| 16 | + that told you what to look at. | ||
| 17 | + | ||
| 18 | + FRQ_JOT=/tmp/frq-jump.log just flutter-desktop run | ||
| 19 | + | ||
| 20 | + Written for a jump that fired, scrolled, and was silently undone in the same | ||
| 21 | + frame — see `frq.hiccup/end-ward!`. What settled it was not one line but the | ||
| 22 | + order of several from different callbacks, which is the shape of question | ||
| 23 | + this answers well: who ran, in what order, with what numbers. A debugger | ||
| 24 | + cannot ask it, because stopping the app is what makes the frame stop being | ||
| 25 | + a frame." | ||
| 26 | + (:require ["dart:io" :as io])) | ||
| 27 | + | ||
| 28 | +(defonce ^:private sink | ||
| 29 | + ;; Read once. An env var does not change under a running app, and this is | ||
| 30 | + ;; called from inside build and post-frame callbacks. | ||
| 31 | + (delay (let [p (get (.-environment io/Platform) "FRQ_JOT")] | ||
| 32 | + (when (and p (seq p)) p)))) | ||
| 33 | + | ||
| 34 | +(defn on? | ||
| 35 | + "Whether anything is listening, for a caller with expensive diagnostics to | ||
| 36 | + build. `jot!` asks this itself; this is for the `(when (debug/on?) ...)` | ||
| 37 | + around a string that costs something to make." | ||
| 38 | + [] | ||
| 39 | + (some? @sink)) | ||
| 40 | + | ||
| 41 | +(defn jot! | ||
| 42 | + "Append one line, when `FRQ_JOT` named a file. Answers nil either way. | ||
| 43 | + | ||
| 44 | + Never throws: a diagnostic that takes the app down with it is worse than no | ||
| 45 | + diagnostic, and the path may be unwritable for reasons that have nothing to | ||
| 46 | + do with what is being looked at." | ||
| 47 | + [& parts] | ||
| 48 | + (when-let [path @sink] | ||
| 49 | + (try | ||
| 50 | + (.writeAsStringSync (io/File. path) | ||
| 51 | + (str (apply str parts) "\n") | ||
| 52 | + .mode io/FileMode.append) | ||
| 53 | + (catch Exception _ nil))) | ||
| 54 | + nil) | ||
modified
flutter/src/frq/net/dart.cljd +21 -3 | @@ -17,6 +17,7 @@ | ||
| 17 | 17 | (:require ["dart:convert" :as conv] |
| 18 | 18 | ["dart:developer" :as dev] |
| 19 | 19 | ["dart:io" :as io] |
| 20 | + [frq.debug :as debug] | |
| 20 | 21 | [frq.irc.parse :as parse])) |
| 21 | 22 | |
| 22 | 23 | ;; Whether to log every line in and out, under the name `frq.wire`. |
| @@ -26,8 +27,16 @@ | ||
| 26 | 27 | ;; server sent it back. A field on a parsed message says what we made of a |
| 27 | 28 | ;; line; only the line says what arrived. |
| 28 | 29 | ;; |
| 29 | -;; `dart:developer` rather than stdout, so it reaches both targets the same | |
| 30 | -;; way — a terminal under `just flutter-desktop`, and `adb logcat` on a phone. | |
| 30 | +;; `dart:developer` rather than stdout, because stdout is nowhere: `print` in | |
| 31 | +;; a compiled bundle writes to a `*out*` nothing is holding. `logcat` picks | |
| 32 | +;; this up on a phone, which is what it is for. | |
| 33 | +;; | |
| 34 | +;; It does not reach a terminal under `just flutter-desktop`, though — that | |
| 35 | +;; recipe launches the bundle itself, and `dev/log` goes to the VM service, | |
| 36 | +;; not to the process's output. This comment used to claim otherwise, and a | |
| 37 | +;; session spent looking for the wire log on the desktop is how that was | |
| 38 | +;; found out. `frq.debug` is the way to see it there: `FRQ_JOT` names a file | |
| 39 | +;; and every line lands in it. | |
| 31 | 40 | ;; |
| 32 | 41 | ;; A comment rather than a docstring because `defonce` takes none: it is |
| 33 | 42 | ;; `(defonce name expr)` and nothing else, and the extra form is an arity |
| @@ -36,7 +45,16 @@ | ||
| 36 | 45 | |
| 37 | 46 | (defn- wire! [direction line] |
| 38 | 47 | (when @wire-log? |
| 39 | - (dev/log (str direction " " line) .name "frq.wire"))) | |
| 48 | + (dev/log (str direction " " line) .name "frq.wire") | |
| 49 | + ;; And to the file when one is asked for, which is the only way to read | |
| 50 | + ;; this on a desktop build. Redacted the way the desktop's own trace is: | |
| 51 | + ;; a line beginning `AUTHENTICATE` carries the credential itself, and a | |
| 52 | + ;; log is something you paste into a bug report. | |
| 53 | + (when (debug/on?) | |
| 54 | + (debug/jot! direction " " | |
| 55 | + (if (.startsWith (str line) "AUTHENTICATE ") | |
| 56 | + "AUTHENTICATE <redacted>" | |
| 57 | + line))))) | |
| 40 | 58 | |
| 41 | 59 | (defn ^:async connect! |
| 42 | 60 | "Open a connection and start reading it. |
| @@ -17,6 +17,7 @@ | |||
| 17 | (:require ["dart:convert" :as conv] | 17 | (:require ["dart:convert" :as conv] |
| 18 | ["dart:developer" :as dev] | 18 | ["dart:developer" :as dev] |
| 19 | ["dart:io" :as io] | 19 | ["dart:io" :as io] |
| 20 | + [frq.debug :as debug] | ||
| 20 | [frq.irc.parse :as parse])) | 21 | [frq.irc.parse :as parse])) |
| 21 | 22 | ||
| 22 | ;; Whether to log every line in and out, under the name `frq.wire`. | 23 | ;; Whether to log every line in and out, under the name `frq.wire`. |
| @@ -26,8 +27,16 @@ | |||
| 26 | ;; server sent it back. A field on a parsed message says what we made of a | 27 | ;; server sent it back. A field on a parsed message says what we made of a |
| 27 | ;; line; only the line says what arrived. | 28 | ;; line; only the line says what arrived. |
| 28 | ;; | 29 | ;; |
| 29 | -;; `dart:developer` rather than stdout, so it reaches both targets the same | 30 | +;; `dart:developer` rather than stdout, because stdout is nowhere: `print` in |
| 30 | -;; way — a terminal under `just flutter-desktop`, and `adb logcat` on a phone. | 31 | +;; a compiled bundle writes to a `*out*` nothing is holding. `logcat` picks |
| 32 | +;; this up on a phone, which is what it is for. | ||
| 33 | +;; | ||
| 34 | +;; It does not reach a terminal under `just flutter-desktop`, though — that | ||
| 35 | +;; recipe launches the bundle itself, and `dev/log` goes to the VM service, | ||
| 36 | +;; not to the process's output. This comment used to claim otherwise, and a | ||
| 37 | +;; session spent looking for the wire log on the desktop is how that was | ||
| 38 | +;; found out. `frq.debug` is the way to see it there: `FRQ_JOT` names a file | ||
| 39 | +;; and every line lands in it. | ||
| 31 | ;; | 40 | ;; |
| 32 | ;; A comment rather than a docstring because `defonce` takes none: it is | 41 | ;; A comment rather than a docstring because `defonce` takes none: it is |
| 33 | ;; `(defonce name expr)` and nothing else, and the extra form is an arity | 42 | ;; `(defonce name expr)` and nothing else, and the extra form is an arity |
| @@ -36,7 +45,16 @@ | |||
| 36 | 45 | ||
| 37 | (defn- wire! [direction line] | 46 | (defn- wire! [direction line] |
| 38 | (when @wire-log? | 47 | (when @wire-log? |
| 39 | - (dev/log (str direction " " line) .name "frq.wire"))) | 48 | + (dev/log (str direction " " line) .name "frq.wire") |
| 49 | + ;; And to the file when one is asked for, which is the only way to read | ||
| 50 | + ;; this on a desktop build. Redacted the way the desktop's own trace is: | ||
| 51 | + ;; a line beginning `AUTHENTICATE` carries the credential itself, and a | ||
| 52 | + ;; log is something you paste into a bug report. | ||
| 53 | + (when (debug/on?) | ||
| 54 | + (debug/jot! direction " " | ||
| 55 | + (if (.startsWith (str line) "AUTHENTICATE ") | ||
| 56 | + "AUTHENTICATE <redacted>" | ||
| 57 | + line))))) | ||
| 40 | 58 | ||
| 41 | (defn ^:async connect! | 59 | (defn ^:async connect! |
| 42 | "Open a connection and start reading it. | 60 | "Open a connection and start reading it. |
modified
src/frq/irc.clj +18 -4 | @@ -104,14 +104,29 @@ | ||
| 104 | 104 | (when (:outbox conn) |
| 105 | 105 | (flush-outbox-tls! conn))) |
| 106 | 106 | |
| 107 | +(defn- trace! | |
| 108 | + "One line of the conversation with the server, under FRQ_TRACE. | |
| 109 | + | |
| 110 | + Whole, not the first hundred characters: the tags come first and a line | |
| 111 | + carries a signature long enough to push every other tag past that cut, so | |
| 112 | + the truncated form could not answer what a `+reply` said — or whether there | |
| 113 | + was one — which is the question the trace exists for. | |
| 114 | + | |
| 115 | + Except an `AUTHENTICATE` payload, which is the credential itself. A trace is | |
| 116 | + something you paste into a bug report, and a session token is not." | |
| 117 | + [dir line] | |
| 118 | + (when (System/getenv "FRQ_TRACE") | |
| 119 | + (let [line (str/trimr line) | |
| 120 | + line (if (str/starts-with? line "AUTHENTICATE ") "AUTHENTICATE <redacted>" line)] | |
| 121 | + (binding [*out* *err*] (println (str "frq/irc: " dir " " line)))))) | |
| 122 | + | |
| 107 | 123 | (defn- flush-outbox-tls! [conn] |
| 108 | 124 | (let [pending (locking (:lock conn) |
| 109 | 125 | (let [q @(:outbox conn)] |
| 110 | 126 | (reset! (:outbox conn) []) |
| 111 | 127 | q))] |
| 112 | 128 | (doseq [text pending] |
| 113 | - (when (System/getenv "FRQ_TRACE") | |
| 114 | - (binding [*out* *err*] (println "frq/irc: >>" (str/trimr text)))) | |
| 129 | + (trace! ">>" text) | |
| 115 | 130 | (try (write! conn text) |
| 116 | 131 | (catch Exception e |
| 117 | 132 | (binding [*out* *err*] (println "frq/irc: write failed:" (or (ex-message e) (str e)))) |
| @@ -155,8 +170,7 @@ | ||
| 155 | 170 | lines (str/split acc #"\r?\n" -1) |
| 156 | 171 | complete (butlast lines)] |
| 157 | 172 | (doseq [line complete :when (seq (str/trim line))] |
| 158 | - (when (System/getenv "FRQ_TRACE") | |
| 159 | - (binding [*out* *err*] (println "frq/irc: <<" (subs line 0 (min 100 (count line)))))) | |
| 173 | + (trace! "<<" line) | |
| 160 | 174 | (let [msg (parse-line line)] |
| 161 | 175 | (when (= "PING" (:command msg)) |
| 162 | 176 | (send-line! conn (str "PONG :" (first (:params msg))))) |
| @@ -104,14 +104,29 @@ | |||
| 104 | (when (:outbox conn) | 104 | (when (:outbox conn) |
| 105 | (flush-outbox-tls! conn))) | 105 | (flush-outbox-tls! conn))) |
| 106 | 106 | ||
| 107 | +(defn- trace! | ||
| 108 | + "One line of the conversation with the server, under FRQ_TRACE. | ||
| 109 | + | ||
| 110 | + Whole, not the first hundred characters: the tags come first and a line | ||
| 111 | + carries a signature long enough to push every other tag past that cut, so | ||
| 112 | + the truncated form could not answer what a `+reply` said — or whether there | ||
| 113 | + was one — which is the question the trace exists for. | ||
| 114 | + | ||
| 115 | + Except an `AUTHENTICATE` payload, which is the credential itself. A trace is | ||
| 116 | + something you paste into a bug report, and a session token is not." | ||
| 117 | + [dir line] | ||
| 118 | + (when (System/getenv "FRQ_TRACE") | ||
| 119 | + (let [line (str/trimr line) | ||
| 120 | + line (if (str/starts-with? line "AUTHENTICATE ") "AUTHENTICATE <redacted>" line)] | ||
| 121 | + (binding [*out* *err*] (println (str "frq/irc: " dir " " line)))))) | ||
| 122 | + | ||
| 107 | (defn- flush-outbox-tls! [conn] | 123 | (defn- flush-outbox-tls! [conn] |
| 108 | (let [pending (locking (:lock conn) | 124 | (let [pending (locking (:lock conn) |
| 109 | (let [q @(:outbox conn)] | 125 | (let [q @(:outbox conn)] |
| 110 | (reset! (:outbox conn) []) | 126 | (reset! (:outbox conn) []) |
| 111 | q))] | 127 | q))] |
| 112 | (doseq [text pending] | 128 | (doseq [text pending] |
| 113 | - (when (System/getenv "FRQ_TRACE") | 129 | + (trace! ">>" text) |
| 114 | - (binding [*out* *err*] (println "frq/irc: >>" (str/trimr text)))) | ||
| 115 | (try (write! conn text) | 130 | (try (write! conn text) |
| 116 | (catch Exception e | 131 | (catch Exception e |
| 117 | (binding [*out* *err*] (println "frq/irc: write failed:" (or (ex-message e) (str e)))) | 132 | (binding [*out* *err*] (println "frq/irc: write failed:" (or (ex-message e) (str e)))) |
| @@ -155,8 +170,7 @@ | |||
| 155 | lines (str/split acc #"\r?\n" -1) | 170 | lines (str/split acc #"\r?\n" -1) |
| 156 | complete (butlast lines)] | 171 | complete (butlast lines)] |
| 157 | (doseq [line complete :when (seq (str/trim line))] | 172 | (doseq [line complete :when (seq (str/trim line))] |
| 158 | - (when (System/getenv "FRQ_TRACE") | 173 | + (trace! "<<" line) |
| 159 | - (binding [*out* *err*] (println "frq/irc: <<" (subs line 0 (min 100 (count line)))))) | ||
| 160 | (let [msg (parse-line line)] | 174 | (let [msg (parse-line line)] |
| 161 | (when (= "PING" (:command msg)) | 175 | (when (= "PING" (:command msg)) |
| 162 | (send-line! conn (str "PONG :" (first (:params msg))))) | 176 | (send-line! conn (str "PONG :" (first (:params msg))))) |