Clojurians Log v2

We downgraded to Clojure 1.12.2 on Friday. It has been 4 days since then, and the bug has not reappeared yet. The bug had been occurring around 2-3 times per week on average. However, we once had a 1.5-week gap between two occurrences, so we still cannot say for sure that the issue has been fixed. I just wanted to give you folks an update. I’ll report back either if the bug happens again or after 10 bug-free days. 🤞

Are you sure result is a regular map? Aleph uses some custom map types internally which may in very rare cases lead to weird compatibility issues.

@vale result is a clojure.lang.PersistentArrayMap @suvratapte , both get and find end up using the same https://github.com/clojure/clojure/blob/clojure-1.12.5/src/jvm/clojure/lang/PersistentArrayMap.java#L315 algorithm Switch your debugging report to find. (get {:a nil} :a) and (get {} :a) both returns nil, but it mean distinct things (find {:a nil} :a) return [:a nil] and (get {} :a) returns nil, making it easier to understand where the bug is.

@vale result is a clojure.lang.PersistentArrayMap

@vale @souenzzo really appreciate you folks taking the time to check this. Thank you! 🙂

@suvratapte switching from get to find is just to make it clearer for those who are debugging if it "could not find the value" or "if the value is null" - In some ways, it's equivalent to using :not-found key I'm very interested and I'll be following your journey over on ask

Yeah, the :not-found experiment confirmed that the value wasn't nil, but the key couldn't be found. Thanks for the interest. It indeed is quite intriguing. The next step is to try downgrading Clojure. I'll report what we find out. 🙂

for the record, I don't have any reason to believe there is an issue with the changes in latest Clojure (or we wouldn't have released it), but as a professional debugger, I am triggered by the coincidence of timing at least to want to rule out a connection.

how sure are you that the nil? being called is clojure.core/nil?

also maybe try replacing the nil? check in the and with ((identity nil?) ....) (will force calling the function via the var instead of the compiler possibly inlining)

shot in the dark: keyword constructed in an odd way that avoids the cache that allows comparison of keywords based on identity? eg. (identical k :k) ends up being false because of a weird code path?

even better: check (identical? k (keyword (name k)))

the ask shows identical? returning true already, so the initial hypothesis about keywords seems to be ruled out already. and it mentions reloading code "fixing" the issue, which sounds like a compiler issue to me. clojure.core/nil? is inlined as (clojure.lang.Util/identical x nil) , forcing it to be a higher oder functions like ((identity nil?) ...) forces the compiler to treat it as a regular function call and not inline it

other interesting things to try might be replacing the call to nil? with a call like (identical? nil ...) to see if that changes the behavior. the other thing, and this is even whackier, you could try replacing and with (if ... (if ... true false) false)

are you aot compiling? if so what is the compilation evironment like? if and loose's it's macro flag somehow you can get weird results

user=> (alter-meta! #'and dissoc :macro)
{:added "1.0", :ns #object[clojure.lang.Namespace 0x6dba847b "clojure.core"], :name and, :file "clojure/core.clj", :column 1, :line 844, :arglists ([] [x] [x & next]), :doc "Evaluates exprs one at a time, from left to right. If a form\n  returns logical false (nil or false), and returns that value and\n  doesn't evaluate any of the other expressions, otherwise it returns\n  the value of the last expr. (and) returns true."}
user=> (and false false)
true
user=>

I am also wondering about the "recompiling the affected namespaces via nREPL" from the original ticket

which leads me also to wonder what the "original" compilation was and why nREPL is involved in your production environment

So in the logging there you can add something that logs the result of (and false false)

how sure are you that the nil? being called is clojure.core/nil?

the compilation environment is the in memory state of clojure (namespaces, vars, etc) when a given bit of code is compiled. so for example if something silly like (alter-meta! #'and dissoc :macro) was run then the namespace your code is in was loaded, that code would have been compiled in a compilation environment where and isn't macro

it is common for the compilation environment to be messed with by tooling (like nrepl middlewares, etc) or stuff like a user.clj file

the reason I asked about aot is in that case you can have a larger divergence in the compilation environment and the runtime environment (the compilation environment was in a different process)

(the runtime environment is the state of the clojure runtime when code is run)

Thanks for the explanation @hiredman > it is common for the compilation environment to be messed with by tooling (like nrepl middlewares, etc) or stuff like a user.clj file This bug has been present since a ~3 months now. We did not have the nrepl dependency when the bug started occurring. We only added it when we decided to run an nREPL server for debugging. We do not have a user.clj or any middleware which seems suspicious. As far as I can tell, there's nothing weird in the compilation and runtime environment that would shadow / alter any state. The jar is built with uberdeps and run with clojure.main -m .... But I'm happy to share specifics if that helps.

the expression (*and* (map? result) (nil? (:payload result))) needs to be attacked. you've looked at result and :payload, but the other things in that expression are and and nil? which is why I suggested ways to examine their behavior

That's a good idea. I will change the code to log the results of both the branches as you've mentioned here: https://clojurians.slack.com/archives/C03S1KBA2/p1779130380034179?thread_ts=1779097281.433139&cid=C03S1KBA2 If you want me to log anything in specific, please let me know. 🙂

add :and (and false false) to the map you are logging. I don't have a mechanism for why and would be losing it's macro flag(there are things we could do to figure that out), I think it just about perfectly matches the described symptoms, and that will help confirm or rule that out (it isn't perfect about ruling it out, but should be a good approximation without writing your own macro to capture the state of #'and at macro expansion time)

Will do this and give you an update as soon as the bug happens again. Thanks a ton!

can you share this whole function? I think that would help a lot

is there any chance you have for example refer'ed or created a local symbol that has replaced the meaning of any symbol there

Sure, here's the whole function:

(ns <ns-name>
  (:require
   [aleph.http :as http]
   [aleph.tcp :as tcp]
   [aws-xray-sdk-clj.core :as xray]
   [byte-streams]
   [cambium.codec :as log-codec]
   [cambium.core :as log]
   [cambium.logback.json.flat-layout :as flat]
   [clojure.core.async :as async]
   [clojure.edn]
   [clojure.set :as set]
   [clojure.string :as str]
   [cognitect.transit :as transit]
   [<internal-ns>.diff :as diff]
   [<internal-ns>.jwt :as jwt]
   [<internal-ns>.metrics :as metrics]
   [<internal-ns>.xray :as xrayutils]
   [com.unbounce.encors.aleph :as encor]
   [gloss.core :as gloss]
   [gloss.core.protocols :as gloss-p]
   [gloss.data.bytes :as gloss-b]
   [ :as io]
   [iapetos.core :as prometheus]
   [manifold.bus :as bus]
   [manifold.deferred :as d]
   [manifold.stream :as stream]
   [manifold.time :as t]
   [msgpack.core :as msg]
   [nrepl.server :as nrepl])
  (:import
   [com.auth0.jwt.exceptions SignatureVerificationException TokenExpiredException]
   [ ByteArrayInputStream ByteArrayOutputStream File]
   [java.nio ByteBuffer]
   [java.util.concurrent Executors]
   [java.util.concurrent.locks ReentrantLock]
   [org.apache.commons.compress.compressors.deflate DeflateCompressorInputStream]
   [org.slf4j.bridge SLF4JBridgeHandler]))


(defn read-message [message with-compression?]
  (try
    (if with-compression?
      (with-open [ins  (ByteArrayInputStream. message)
                  baos (ByteArrayOutputStream.)
                  lzma (DeflateCompressorInputStream. ins)]
        (.transferTo lzma baos)
        (let [decompressed (.toByteArray baos)]
          (with-open [bais (ByteArrayInputStream. decompressed)]
            (let [result (transit/read (transit/reader bais :json))]
              (when (and (map? result) (nil? (:payload result)))
                (try
                  (let [payload-key (->> (keys result)
                                         (filter #(.contains (pr-str %) "payload"))
                                         first)
                        payload-via-key (when payload-key (get result payload-key))
                        payload-via-kw-invoke  (:payload result ::not-found)
                        payload-via-get        (get result :payload ::not-found)]
                    (log/warn {:result-keys (pr-str (keys result))
                               :result-key-types (pr-str (mapv (fn [k] {:key (pr-str k) :type (str (type k)) :keyword? (keyword? k)}) (keys
                                                                                                                                      result)))

                               :payload-key-found (pr-str payload-key)
                               :payload-key-type (str (type payload-key))

                               :payload-key-equals-literal? (= payload-key :payload)
                               :payload-key-identical? (identical? payload-key :payload)
                               :payload-key-hashcode (when payload-key (hash payload-key))
                               :payload-literal-hashcode (hash :payload)
                               :payload-key-classloader (when payload-key
                                                          (str (.getClassLoader (class payload-key))))
                               :payload-literal-classloader (str (.getClassLoader (class :payload)))

                               :payload-key-name-length (when (keyword? payload-key) (count (name payload-key)))
                               :payload-key-name-codepoints (when (keyword? payload-key)
                                                              (mapv #(format "U+%04X" %)
                                                                    (.toArray (.codePoints ^String (name payload-key)))))
                               :payload-key-name-bytes (when (keyword? payload-key)
                                                         (mapv #(format "0x%02X" (bit-and % 0xFF))
                                                               (.getBytes ^String (name payload-key) "UTF-8")))
                               :payload-literal-name-bytes (mapv #(format "0x%02X" (bit-and % 0xFF))
                                                                 (.getBytes "payload" "UTF-8"))
                               :payload-key-ns (when (keyword? payload-key) (namespace payload-key))

                               :payload-via-found-key-nil? (nil? payload-via-key)
                               :payload-via-found-key-type (str (type payload-via-key))

                               :payload-via-kw-invoke-missing? (identical? payload-via-kw-invoke ::not-found)
                               :payload-via-kw-invoke-nil?     (nil? payload-via-kw-invoke)
                               :payload-via-kw-invoke-type     (str (type payload-via-kw-invoke))
                               :payload-via-get-missing?       (identical? payload-via-get ::not-found)
                               :payload-via-get-nil?           (nil? payload-via-get)
                               :payload-via-get-type           (str (type payload-via-get))
                               :payload-kw-invoke-equals-get?  (= payload-via-kw-invoke payload-via-get)

                               :payload-id-hash-log-site  (System/identityHashCode :payload)
                               :payload-key-id-hash       (System/identityHashCode payload-key)

                               :result-type (str (type result))}
                              "nil payload detected - extended diagnostics"))
                  (catch Exception e
                    (log/warn e "Extended diagnostics failed; continuing message processing"))))
              result))))
      (with-open [baos (ByteArrayInputStream. (bytes (byte-array (map byte message))))]
        (transit/read (transit/reader baos :json))))
    (catch Exception e (log/error e "EXCEPTION IN READ MESSAGE"))))

it's fairly important that the map is being read out of transit - what version of transit-clj are you on?

The bug happened again this morning (CEST) and the results are even more confusing. We printed the results of the branches and the whole when guard in the when body.

(map? result) => true

(nil? (:payload result)) => false

(and (map? result) (nil? (:payload result))) => false

(if (map? result)
  (if (identical? nil (:payload result))
    :true-inner
    :false-inner)
  :false-outer) => :false-inner

did you do the (and false false) thing?

(and (map? result) (nil? (:payload result))) => false

how are you correlating that these log messages are all happening on the same thread?

hmmm I guess logging the single big map like that makes it so it doesn't matter

Turn the test expression of the when into a def'ed predicate (def bogus? [result] ...) and then the when is (when (bogus? result) ...) pulling it out may effect things so it doesn't reproduce, but if it does it gives you a named handle on the "bad" code. So you can run the exact same bytecode generates by the clojure compiler in the body of the when, and likely the same jitt'ed code (but not for sure). To control for the "same" expression generating different code with different behavior in different contexts.

when you say you "recompile", what exactly does that mean? I assume you are not literally calling compile

if you are able to modify and restore the read-message and see a change in behavior then I think that implies something in the bytecode for that function and what I'd really want to compre is the bytecode of the function class before and after you "recompile". the class file is held in the classloader and is reachable via

leaning on AI to do the boring part:

(require '[ :as io])

(defn save-fn-class [v out-dir]
  (let [cls-name (.getName (class @v))                       ; e.g. "my.ns$my_fn"
        res-path (str (.replace cls-name \. \/) ".class")    ; "my/ns$my_fn.class"
        resource (io/resource res-path)
        out-file (io/file out-dir (str cls-name ".class"))]
    (when-not resource
      (throw (ex-info "No class resource found" {:path res-path})))
    (with-open [in  (io/input-stream resource)
                out (io/output-stream out-file)]
      (io/copy in out))
    (.getAbsolutePath out-file)))

(save-fn-class #'my.ns/my-fn "/tmp")

I believe that is only true for aot'd code, I don't think classes defined via dynamicclassloader can be grabbed that way

ah true, but you could reach into the DCL for that

I don't think it keeps the bytes

oh!

it does?

yeah, maybe not

I think it just has the class

I am now remembering walking this path several times before

I probably hacked the DCL :)

sometimes I use a DCL that saves the class bytes off to a well-known place as it loads

> did you do the (and false false) thing? No, I missed adding that to the logs. But as you say, the results of the two operands of and and the whole and expression rules that out. > Turn the test expression of the when into a def'ed predicate (def bogus? [result] ...) and then the when is (when (bogus? result) ...) pulling it out may effect things so it doesn't reproduce, but if it does it gives you a named handle on the "bad" code. So you can run the exact same bytecode generates by the clojure compiler in the body of the when, and likely the same jitt'ed code (but not for sure). To control for the "same" expression generating different code with different behavior in different contexts. This is a great idea @hiredman. I'll try it out. Thanks! > when you say you "recompile", what exactly does that mean? @alexmiller Sorry, I should have been more specific. By "compile", I mean using cider-eval-defun-at-point (via Emacs). But it's a good idea to compare the two versions of bytecode. I'll check if it's possible.

We're on 1.1.357

I should also highlight that we have 10 instances running and so far we've always seen only one of the instances being affected at a time. Usually 1 to 2 times a week. The bug starts suddenly and then doesn't stop. We just kill the instance. The affected instance works completely fine before the bug starts.

Is the transit data generated by browsers? That is the transit client version? has considered an intentionally bad transit (i mean - someone trying to "attack" you)

The data is generated by another internal service. It's financial data. Basically a stream of trade values with the exact same structure. At the rate of one payload every 250 ms. Since the same data is consumed by all instances, corruption in the data is unlikely. We've actually examined specific traces and confirmed that the data sent by the upstream service was indeed correct.

Are you writing multiple transit payloads using the same writer?

(with-open [out (ByteArrayOutputStream. 4096)
            writer (transit/writer out :json)]
  (transit/write writer "foo")
  (transit/write writer {:a [1 2]}))

Transit does map key keyword caching, which certainly seems like it should be a suspect here

That caching comes into play both during writing and reading. Fortunately you have the data in the middle when this happens - have you inspected that transit data directly? Given everything else I'd suspect the read side cache first

> Are you writing multiple transit payloads using the same writer? @souenzzo No, we're not. > Transit does map key keyword caching, which certainly seems like it should be a suspect here @alexmiller yes, that was my suspicion as well. So we forked transit-clj and transit-java and added logs. As far as I can tell, things are working correctly. But if you want me to check anything specific, I'd be happy to do that.

> have you inspected that transit data directly? Yes, we did that. But I'll try to double check and see if we can inspect anything more.

My new hypothesis is something to do with removing the readHandlerCache in transit-java in 1.1.389. Does that version change (transitive to transit-clj) correlate to lib updates around the time you started seeing the issue?

releases were Feb 4, transit-clj 1.1.347

I'd be interested in seeing if falling back to transit-clj 1.0.329 made it go away

We were on 1.0.329 until August 1, 2024. But we can't say if the bug didn't exist before. We will check and see if we can downgrade transit-clj. If it is feasible, we will downgrade and let you know. Really appreciate your help here @alexmiller 🙏

That timeline doesn't make sense, the next version didn't exist until Feb 2026, so I'm wondering when you updated past that line

And if that correlates with starting to see the problem

We changed from 1.0.329 to 1.0.333 (released in April 2023) on August 1, 2024. Then from 1.0.333 to 1.1.357 on March 17, 2026. The problem existed with 1.0.333 as well. We updated to 1.1.357 to check if that fixes the problem. But it didn't.

But if it was a transit-clj / transit-java issue, recompiling with nrepl shouldn't fix it, right?

Can two messages from the same connection ever be deserialized on different threads? I would like to rule out reader reuse.

If it is transit that will be really interesting, because I just don't see how it is possible. Given the logging shown it seems like it would have to be mutating the contents of a persistentarraymap, which is not impossible but requires work to do, and I just don't think transit-java (which doesn't deal in clojure values?) and transit-clj do that work

Like it would be one thing for a bad value from a cache or something to make it into the persistentmap and always be there, but for the value to appear to be missing and then be there is another kettle of fish

although, maybe if you have custom transit read handlers that explicit construct persistentarraymaps using the constructor where you can pass in your own array(not sure if that ctor is even public)?

> Can two messages from the same connection ever be deserialized on different threads? I would like to rule out reader reuse. @jarrodctaylor No, I'm certain that this doesn't happen. > maybe if you have custom transit read handlers that explicit construct persistentarraymaps using the constructor where you can pass in your own array @hiredman We don't have custom readers.

Unfortunately the bug was seen again today. @hiredman I had followed your suggestion and defined separate functions for the when guard:

(defn result-map? [result] (map? result))

(defn payload-nil? [result] (nil? (:payload result)))

(defn invalid-message? [result]
  (and (result-map? result)
       (payload-nil? result)))

fascinating. when (payload-nil? result) and (nil? (:payload result)) is result for sure the same object, not just an identically constructed object? you may be at the point where capturing the generated byte code would be useful, but hard to do that. what happens if you add an (assert (payload-nil? {})) right after the payload-nil? definition. It would be useful to know if calling the payload-nil? function always misbehaves or only somtimes

if you can pop a repl maybe check the value of the payload-nil? var, does the classname for the function make sense and appear to actually have come from that definition

hmmm, are classes serializable? can you just get the bytecode that way?

(they are, not sure what you get from a serialized class though)

ah, no, you don't get the bytecode of course 😕

Hmm, yeah I'll carryout some of these experiments and also read up about how I can get the byte code. I also want to check if JVM does any "runtime optimizations" for hot code paths. The only pattern regarding this bug is that it never occurs right after a deployment. Which makes me think that JVM is changing something? But then that doesn't explain why only one out of 10 instances gets affected.

We are also thinking of downgrading JVM and seeing if that helps.

yeah, if this code is being run often in the same jvm and then suddenly starts producing a different answer either something changed the value of the var so it points to a different function (checking the class name of the function will help checking this) or the jit doing something weird