Fork me on GitHub
#chlorine-clover
<
2020-09-11
>
jba10:09:06

Hello, I try to use https://github.com/replikativ/datahike-jdbc with socket-repl & chlorine and for to some reason evaluating a block with a transaction freeze the block in an endless evaluation (ie. the wheel keep turning) Any ideas where that comes from? If I do the same using nREPL it's working.

jba10:09:17

A transaction returns a record [1], I don't know if that's matter or not. [1] https://github.com/replikativ/datahike/blob/a6614482fc61483b82b7629716cace89f1f86b5e/src/datahike/db.cljc

seancorfield17:09:42

@mauricio.szabo Might be able to point you at some debugging for that @jba but I can't think of a reason for a code block to just hang if it is valid code and executes fine directly in a REPL.

mauricio.szabo17:09:28

Probably because of UNREPL. There's an open issue on that - sometimes, it returns an invalid EDN and that freezes the whole evaluation (and sometimes, Chlorine itself - it only starts to eval again when you disconnect/reconnect)

mauricio.szabo17:09:53

Datahike is known to cause this issue, some datomic evaluation too 😞

seancorfield17:09:18

Hmm, I've seen exceptions reported from unrepl but not hangs. Good to know. Or rather, bad to know, I guess.

jba17:09:11

Yes, look like what you are describing. Is it this issue https://github.com/Unrepl/unrepl/issues/52 ? What would be the way to debug it?

mauricio.szabo17:09:49

Probably the only way to debug is with tellnet. But if you're using datahike, is exactly the problem you're having - I remember having this exactly same problem with datahike, and having to change to nREPL to work with it 😞

jba17:09:01

good old network debugging, that's gonna be fun 😅 I will give it a try next week. Thanks for your work on chlorine btw, it's a great tool :)

3
jba14:09:10

I investigate the problem with wireshark and I found this part is returned before the eval get stuck:

jba14:09:16

536870913 :db/txInstant #inst \"2020-09-18T13:38:12.010-00:00\" 5" #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22549)}] {:bean {#unrepl/... nil #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22546)}}}] #unrepl/object [#unrepl/browsable [#unrepl.java/class [datahike.datom.Datom #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22551)}] #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22552)}] #datahike/Datom [1 :db/ident :city_name 536870913 true] "0x1e560feb" "#datahike/Datom [1 :db/ident :city_name 536870913 true]" {:bean {#unrepl/... nil #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22550)}}}] #unrepl/object [#unrepl/browsable [#unrepl.java/class [datahike.datom.Datom #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22554)}] #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22555)}] #datahike/Datom [1 :db/valueType :db.type/string 536870913 true] "0x1935e078" "#datahike/Datom [1 :db/valueType :db.type/string 536870913 true]" {:bean {#unrepl/... nil #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22553)}}}] #unrepl/object [#unrepl/browsable [#unrepl.java/class [#unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22558)}] #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22559)}] #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22560)}]], #unrepl/... nil #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22561)}} 38]
[:prompt {:file "/home/jba/PROJECTS/playground/src/playground/db.clj", :line 29, :column 2, :offset 1576, clojure.core/*warn-on-reflection* false, clojure.core/*ns* #unrepl/browsable [#unrepl/ns playground.db #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22562)}]} 39]
[:prompt {:file "/home/jba/PROJECTS/playground/src/playground/db.clj", :line 30, :column 1, :offset 1577, clojure.core/*warn-on-reflection* false, clojure.core/*ns* #unrepl/browsable [#unrepl/ns playground.db #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22563)}]} 40]

jba14:09:55

for the same eval nrepl return:

{:db-before ...
 :db-after ...
:tx-data [#datahike/Datom [536870915 :db/txInstant #inst "2020-09-18T14:11:11.183-00:00" 536870915 true]], :tempids {:db/current-tx 536870915}

mauricio.szabo14:09:11

Not really - search for a place that returns :eval on wireshark. You'll see that the second argument of the vector that starts with :eval is a map that have duplicated keys

jba14:09:14

that's the full eval:

[:eval #datahike.db.TxReport {:db-before #datahike.db.DB {}, :db-after #datahike.db.DB {1 :db/cardinality, 1 :db/ident, 1 :db/valueType, 536870913 :db/txInstant}, :tx-data [#unrepl/object [#unrepl/browsable [#unrepl.java/class [datahike.datom.Datom #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22547)}] #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22548)}] #datahike/Datom [536870913 :db/txInstant #inst "2020-09-18T13:38:12.010-00:00" 536870913 true] "0x707efc8b" #unrepl/string ["#datahike/Datom [536870913 :db/txInstant #inst \"2020-09-18T13:38:12.010-00:00\" 5" #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22549)}] {:bean {#unrepl/... nil #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22546)}}}] #unrepl/object [#unrepl/browsable [#unrepl.java/class [datahike.datom.Datom #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22551)}] #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22552)}] #datahike/Datom [1 :db/ident :city_name 536870913 true] "0x1e560feb" "#datahike/Datom [1 :db/ident :city_name 536870913 true]" {:bean {#unrepl/... nil #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22550)}}}] #unrepl/object [#unrepl/browsable [#unrepl.java/class [datahike.datom.Datom #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22554)}] #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22555)}] #datahike/Datom [1 :db/valueType :db.type/string 536870913 true] "0x1935e078" "#datahike/Datom [1 :db/valueType :db.type/string 536870913 true]" {:bean {#unrepl/... nil #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22553)}}}] #unrepl/object [#unrepl/browsable [#unrepl.java/class [#unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22558)}] #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22559)}] #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22560)}]], #unrepl/... nil #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22561)}} 38]
[:prompt {:file "/home/jba/PROJECTS/playground/src/playground/db.clj", :line 29, :column 2, :offset 1576, clojure.core/*warn-on-reflection* false, clojure.core/*ns* #unrepl/browsable [#unrepl/ns playground.db #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22562)}]} 39]

jba14:09:46

try to indent it correctly:

[:eval #datahike.db.TxReport 
 {:db-before #datahike.db.DB {},
  :db-after #datahike.db.DB {1 :db/cardinality, 1 :db/ident, 1 :db/valueType, 536870913 :db/txInstant},
  :tx-data [#unrepl/object [#unrepl/browsable [#unrepl.java/class [datahike.datom.Datom #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22547)}] 
                                               #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22548)}] 
                            #datahike/Datom [536870913 :db/txInstant #inst "2020-09-18T13:38:12.010-00:00" 536870913 true] "0x707efc8b" 
                            #unrepl/string ["#datahike/Datom [536870913 :db/txInstant #inst \"2020-09-18T13:38:12.010-00:00\" 5" 
                                            #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22549)}] {:bean {#unrepl/... nil 
                                                                                                                                  #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22546)}}}] 
            #unrepl/object [#unrepl/browsable [#unrepl.java/class [datahike.datom.Datom #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22551)}] 
                                               #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22552)}] 
                            #datahike/Datom [1 :db/ident :city_name 536870913 true] "0x1e560feb" "#datahike/Datom [1 :db/ident :city_name 536870913 true]" {:bean {#unrepl/... nil
                                                                                                                                                                   #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22550)}}}] 
            #unrepl/object [#unrepl/browsable [#unrepl.java/class [datahike.datom.Datom #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22554)}] 
                                               #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22555)}] 
                            #datahike/Datom [1 :db/valueType :db.type/string 536870913 true] "0x1935e078" "#datahike/Datom [1 :db/valueType :db.type/string 536870913 true]" {:bean {#unrepl/... nil 
                                                                                                                                                                                     #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22553)}}}] 
            #unrepl/object [#unrepl/browsable [#unrepl.java/class [#unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22558)}] 
                                               #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22559)}] 
                            #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22560)}]], 
  #unrepl/... nil
  #unrepl/... {:get (unrepl.repl$i9hjMxfOQ2IzbCA5TVia2QQEJNg/fetch :G__22561)}} 38]

jba14:09:00

I see it now, it's coming from :db-after #datahike.db.DB {1 :db/cardinality, 1 :db/ident, 1 :db/valueType, 536870913 :db/txInstant} ?

mauricio.szabo14:09:35

Yes, if you use pr-str, this error does not occur. To be honest, I have no idea why it happens with UNREPL

jba14:09:48

nrepl return this `{:db-after #datahike/DB {:schema {:db/ident {:db/unique :db.unique/identity}, :city_name {:db/ident :city_name, :db/valueType :db.type/string, :db/cardinality :db.cardinality/one}, 1 :city_name}}}

jba14:09:40

for continuing the investigation I should try to reproduce it from a vanilla unrepl?

mauricio.szabo16:09:22

I think it's easier to reproduce from a vanilla unrepl - you won't need the wireshark at all, only telnet and copy-pasting the UNREPL blob over the telnet connection

mauricio.szabo18:09:45

Well, to be honest I'm giving up UNREPL, it's too complicated 😞. The only problem is to find out something that allows for evaluation (by sending file/row infmroation) and break.... so far, only UNREPL and nREPL allows that...

seancorfield19:09:09

I would imagine you could setup something fairly simple that allows for interruption of execution using a future or similar? I guess the bigger problem is interrupted very large results coming back from the evaluation?

mauricio.szabo22:09:50

I believe interruption with future, for example, is quite simple. The problem is the coordination - because I need to somehow "store" the future to be able to cancel it later, and it needs to be persisted between multiple connections. But the file + row is harder :(

jba14:09:10

I investigate the problem with wireshark and I found this part is returned before the eval get stuck: