Re-graph testing issue

[Wolfgang51]

Hey there, I have been having testing issues recently using re-graph.

Background

1. lein doo as testing library and chrome-headless as js-env.
2. [day8.re-frame.test :as rf-test] for re-frame events

Problem

When I run my tests using lein doo chrome-headless test once I will get the output from the console

?[33m08 03 2019 14:41:24.874:WARN [web-server]: ?[39m404: /js/compiled/test/out/goog/deps.js
?[33m08 03 2019 14:41:24.876:WARN [web-server]: ?[39m404: /js/compiled/test/out/cljs_deps.js
HeadlessChrome 72.0.3626 (Windows 10.0.0) WARN: ?[36m're-frame: overwriting', ':event', 'handler for:', {ns: 'slm.olanext.events', name: 'loan-amount.set-in-or-out-of-state', fqn: 'slm.olanext.events/loan-amount.set-in-or-out-of-state', _hash: 1473332321, cljs$lang$protocol_mask$partition0$: 2153775105, cljs$lang$protocol_mask$partition1$: 4096}?[39m


?[1A?[2KHeadlessChrome 72.0.3626 (Windows 10.0.0): Executed 0 of 1?[32m SUCCESS?[39m (0 secs / 0 secs)
?[1A?[2KLOG: ?[36m'Testing slm.olanext.validation-test'?[39m
HeadlessChrome 72.0.3626 (Windows 10.0.0): Executed 0 of 1?[32m SUCCESS?[39m (0 secs / 0 secs)
?[1A?[2KDEBUG: ?[36m'Ignoring graphql-ws event ', {ns: 're-graph.internals', name: 'default', fqn: 're-graph.internals/default', _hash: -1918427164, cljs$lang$protocol_mask$partition0$: 2153775105, cljs$lang$protocol_mask$partition1$: 4096}, ' - ', 'connection_ack'?[39m
HeadlessChrome 72.0.3626 (Windows 10.0.0): Executed 0 of 1?[32m SUCCESS?[39m (0 secs / 0 secs)
?[33m08 03 2019 14:41:55.561:WARN [HeadlessChrome 72.0.3626 (Windows 10.0.0)]: ?[39mDisconnected (0 times), because no message in 30000 ms.
?[1A?[2K?[31mHeadlessChrome 72.0.3626 (Windows 10.0.0) ERROR?[39m
  Disconnected, because no message in 30000 ms.
HeadlessChrome 72.0.3626 (Windows 10.0.0): Executed 0 of 1?[31m DISCONNECTED?[39m (30.015 secs / 0 secs)
?[1A?[2KHeadlessChrome 72.0.3626 (Windows 10.0.0): Executed 0 of 1?[31m DISCONNECTED?[39m (30.015 secs / 0 secs)
Subprocess failed

And in my graph-ql service I get the following stack trace

system=> ERROR com.walmartlabs.lacinia.pedestal.subscriptions - {:event :com.walmartlabs.lacinia.pedestal.subscriptions/error, :line 506}
org.eclipse.jetty.io.EofException: null
        at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:292)
        at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:429)
        at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:322)
        at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:372)
        at org.eclipse.jetty.websocket.common.io.FrameFlusher$Flusher.flush(FrameFlusher.java:153)
        at org.eclipse.jetty.websocket.common.io.FrameFlusher$Flusher.process(FrameFlusher.java:217)
        at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
        at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
        at org.eclipse.jetty.websocket.common.io.FrameFlusher.enqueue(FrameFlusher.java:382)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.outgoingFrame(AbstractWebSocketConnection.java:614)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onConnectionStateChange(AbstractWebSocketConnection.java:473)
        at org.eclipse.jetty.websocket.common.io.IOState.notifyStateListeners(IOState.java:184)
        at org.eclipse.jetty.websocket.common.io.IOState.onReadFailure(IOState.java:498)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:666)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:511)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:112)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:672)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:590)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.IOException: An existing connection was forcibly closed by the remote host
        at sun.nio.ch.SocketDispatcher.writev0(Native Method)
        at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:55)
        at sun.nio.ch.IOUtil.write(IOUtil.java:148)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504)
        at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:272)
        ... 20 common frames omitted
ERROR com.walmartlabs.lacinia.pedestal.subscriptions - {:event :com.walmartlabs.lacinia.pedestal.subscriptions/error, :line 506}
org.eclipse.jetty.io.EofException: null
        at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:292)
        at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:429)
        at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:322)
        at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:372)
        at org.eclipse.jetty.websocket.common.io.FrameFlusher$Flusher.flush(FrameFlusher.java:153)
        at org.eclipse.jetty.websocket.common.io.FrameFlusher$Flusher.process(FrameFlusher.java:217)
        at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
        at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
        at org.eclipse.jetty.websocket.common.io.FrameFlusher.enqueue(FrameFlusher.java:382)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.outgoingFrame(AbstractWebSocketConnection.java:614)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onConnectionStateChange(AbstractWebSocketConnection.java:473)
        at org.eclipse.jetty.websocket.common.io.IOState.notifyStateListeners(IOState.java:184)
        at org.eclipse.jetty.websocket.common.io.IOState.onReadFailure(IOState.java:498)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:666)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:511)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:112)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:672)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:590)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.IOException: An existing connection was forcibly closed by the remote host
        at sun.nio.ch.SocketDispatcher.writev0(Native Method)
        at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:55)
        at sun.nio.ch.IOUtil.write(IOUtil.java:148)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504)
        at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:272)
        ... 20 common frames omitted

It seems as though the root of this issue lies within calling ::re-graph/init, here is my test

(deftest foo-test
  (rf-test/run-test-async
   (re-frame/dispatch-sync [::events/initialize-db])
   (re-frame/dispatch [::re-graph/init {:ws-url "ws://localhost:8888/graphql-ws"
                                        :http-url "http://localhost:8888/graphql"
                                        :http-parameters {:with-credentials? false
                                                          :oauth-token "Secret"}
                                        :ws-reconnect-timeout 2000
                                        :resume-subscriptions? true
                                        :connection-init-payload {}}])
   (let [sut (re-frame/subscribe [::subs/validation-message :foo :bar :buzz])]
     (re-frame/dispatch [::events/general-info.set-first-name :foo "lipsum"])
     (rf-test/wait-for [::events/on-field-validity]
                       (is (not (empty? @sut)))))))

Any ideas what my be the problem?

[oliyh]

Hi,

Some observations:

• The re-frame event you are waiting for is never fired, hence the 30s timeout
• The EOF from Lacinia is probably the websocket disconnecting when the process is torn down (which means it is probably connecting properly)

It's not obvious what your test does with re-graph. You initialise it, but it doesn't show you making a query or subscription. What relationship does re-graph have to your validation message?

[Wolfgang51]

Thanks for the response @oliyh, to answer your question

::events/general-info.set-first-name triggers ::events/on-field-validity (which you can see I am waiting with (rf-test/wait-for [::events/on-field-validity] ___) which triggers a ::re-graph/query that's response is associated to the db. The associated response is what the subscription ::events/general-info.set-first-name is pointing at.

Unfortunately and fortunately I believe the issue resided in on my network. Or it could have been that the event that was being waited for with (rf-test/wait-for [::events/on-field-validity]) ___ never occurred. None the less I think we can close this issue. Thanks again.

[oliyh]

Hi,

You may find this page useful for debugging to find out what is actually going on:
https://github.com/Day8/re-frame/blob/master/docs/Debugging.md

Hope this helps, let me know if you have any more questions.