I have a strange error happening from time to time using next.jdbc
I reducing over the result of a jdbc/plan and then call twice select-keys on each row
Last week I got this exception once, but I could not reproduce it:
Exception: java.lang.ArrayIndexOutOfBoundsException: Index 196 out of bounds for length 196
at com.mysql.cj.protocol.a.NativePacketPayload.readInteger (NativePacketPayload.java:386)
com.mysql.cj.protocol.a.NativePacketPayload.skipBytes (NativePacketPayload.java:536)
com.mysql.cj.protocol.a.result.TextBufferRow.findAndSeekToOffset (TextBufferRow.java:93)
com.mysql.cj.protocol.a.result.TextBufferRow.getNull (TextBufferRow.java:114)
com.mysql.cj.jdbc.result.ResultSetImpl.getObject (ResultSetImpl.java:1115)
com.mysql.cj.jdbc.result.ResultSetImpl.getObject (ResultSetImpl.java:1438)
next.jdbc.result_set$mapify_result_set$reify__12926.entryAt (result_set.clj:509)
Today, I got an other error at the same line in my code (when select-keys is called), again I cannot reproduce it:
Exception: java.lang.NumberFormatException: Invalid integer format for value 'DE'
at com.mysql.cj.protocol.a.MysqlTextValueDecoder.getLong (MysqlTextValueDecoder.java:232)
com.mysql.cj.protocol.a.MysqlTextValueDecoder.decodeInt8 (MysqlTextValueDecoder.java:126)
com.mysql.cj.protocol.result.AbstractResultsetRow.decodeAndCreateReturnValue (AbstractResultsetRow.java:113)
com.mysql.cj.protocol.result.AbstractResultsetRow.getValueFromBytes (AbstractResultsetRow.java:243)
com.mysql.cj.protocol.a.result.TextBufferRow.getValue (TextBufferRow.java:132)
com.mysql.cj.jdbc.result.ResultSetImpl.getObject (ResultSetImpl.java:1321)
com.mysql.cj.jdbc.result.ResultSetImpl.getLong (ResultSetImpl.java:848)
com.mysql.cj.jdbc.result.ResultSetImpl.getObject (ResultSetImpl.java:1173)
com.mysql.cj.jdbc.result.ResultSetImpl.getObject (ResultSetImpl.java:1438)
next.jdbc.result_set$mapify_result_set$reify__12926.entryAt (result_set.clj:509)
Basically, simplified, what our code does is this:
(with-open [con (jdbc/get-connection ds)
ps (jdbc/prepare con [(my-select-query)])]
(update
(reduce
(fn [{:keys [cnt rows]} row]
(when (:something row)
(telemere/log! {:data (select-keys row some-keys-to-log)} "something-happened"))
(assoc! rows (:id row) (-> row
(select-keys some-keys-to-return)
(merge something-else)))
{:cnt 0
:rows (transient {})}
(jdbc/plan ps))
:rows
persistent!))
this error happens at the second call of select-keys (`(select-keys some-keys-to-return)`) and specifically in a test where (:something row) is true. But only rarely and makes the test flaky.
So I think the issue might either be that select-keys is called twice on row or related to telemere maybe?
Anyone a hint what is going on?at 1st glance i thought that refactoring makes no sense, but now i understand even more, why macros can be dangerous. they can hide control flow and mix up the evaluation timeline in unintuitive ways, opaquely!
what is also not fully clear to me, is there actually any performance difference between plan and execute! if we reduce over the result set and realizing every row anyways?
Like is there a difference between these 2 examples?:
(reduce
(fn [result row]
(conj result (assoc row :new "val")))
[]
(jdbc/plan stmt))
(reduce
(fn [result row]
(conj result (assoc row :new "val")))
[]
(jdbc/execute! stmt))Using select-keys avoids realizing the row.
I think it might be related to telemere. Is log! a macro? Is it batching evaluations behind the scenes, or delaying them?
yes! thank, I think the problem is exactly that. I was able to reproduce the issue now if I run the same test 30 times. Then I always run into this issue. I think I was able to fix my problem by replacing this
(when (:something row)
(telemere/log! {:data (select-keys row some-keys-to-log)} "something-happened"))
with this:
(when (:something row)
(let [log-data (select-keys row some-keys-to-log)]
(telemere/log! {:data log-data} "something-happened")))I know select-keys is not realizing the row. But in my reduce function, I am at the end realizing the row (calling merge on it). -> so eventually every row will be realized
I am wondering if it is still beneficial to use plan over execute!?
The select-keys call produces a new hash map with just the column values you requested. The merge call is operating on that, not the "reducible" from plan at that point.
And for the refactor of the log! call, that makes sense since if the select-keys call happened "later", the row might have changed, since it is a mutable ResultSet behind the scenes when you use plan.
ah, yes, of course, that makes totally sense. thanks a lot 🙏