Failures running browser tests

markdingram · December 18, 2019, 11:00am

I’m struggling to get a reliable setup working for browser cljs tests. I’ve created a test repo here: https://github.com/markdingram/kaocha-browser

npm install && clojure -m kaocha.runner :node-cljs works as expected so the basic setup appears correct.

clojure -m kaocha.runner :browser-cljs works sporadically:

browser-working.txt

However more often it fails with output browser-failing.txt

Rerunning without closing all Chromium windows often succeeds.

Browser is: Chromium Version 78.0.3904.108 (Developer Build) Fedora Project (64-bit)

The two paths diverge at the point where the websocket client should be loaded:

Copying jar:file:/home/mark/.m2/repository/org/clojure/google-closure-library/0.0-20170809-b9c14c6b/google-closure-library-0.0-20170809-b9c14c6b.jar!/goog/string/stringformat.js to out/goog/string/stringformat.js

:cljs/err -> {:val "Analyzing file:/home/mark/.ghq/github.com/lambdaisland/kaocha-cljs/src/kaocha/cljs/websocket_client.cljs\n", :type :cljs/err}

I had a look but I’m unable to quite get a handle on why this is happening myself so would appreciate any help to understand further what’s going on & to resolve.

countgizmo · December 18, 2019, 11:18am

Unfortunately I don’t have a fix for this but I can totally relate. I’m just sharing my experience.
At some point this year I’ve spent around a month battling the same issue that you’re having. At the end I had to give up on it cause no matter what I’ve tried (and I’ve tried a lot of things) I couldn’t get reliable cljs test run in a browser. At the end of the day I had to have cljs tests running so I switched back to figwheel’s test runner.
That being said, I hope you’re successful and I hope one day kaocha-cljs becomes stable (I am using kaocha for clj tests without any problems or pains and it’s super great).

plexus · December 18, 2019, 11:18am

Do you get any errors in the browser console?

plexus · December 18, 2019, 11:58am

Kaocha-cljs is perfectly stable, people use it with the node REPL to great success. I’m convinced these issues stem from the ClojureScript browser REPL environment which Kaocha relies on, not from anything that is under kaocha-cljs’s control.

At some point we should fork these REPL environments to optimize them for machine consumption, this also allows other improvements like reusing existing browser tabs. That said I have no idea when that will happen. This is part of a list of half a dozen bigger improvements that maybe at some point I’ll seek funding for. Until then or until people step up to help out and make Kaocha more of a community project we will likely stay at the current local maximum.

I’ve sunk a lot of time into Kaocha, some of it supported by Clojurists Together, most of it in my own time. Kaocha has steadily seen adoption which is I’m very happy about, but the amount of contributions has been paltry, and not a single person has shown interest in substantially helping to maintain and improve it. So that’s where we are, I may look at some of these things at some point, but I have a lot of things asking for my attention so we’ll see…

Back to the actual issue, Kaocha ClojureScript client failed connecting back. is a very generic error that can have a lot of different causes. It basically means that we started a REPL environment and loaded this client file which does a websocket connect from the js side back to Kaocha, but somehow that connect request never arrives back, so we time out. You can see in your browser-working example what is supposed to happen.

Since there is not a single :cljs/ret in your browser-failing.txt example it seems like the repl environment is misbehaving, we never get anything back.

At this point you need to go look at the js side what happened there, hence my question if you see anything in the browser console log. Any javascript errors? 404s? anything else that may seem relevant?

countgizmo · December 18, 2019, 12:06pm

Side note: I apologise for the misinformation - I did mean in the browser.

And in no way I blame you or kaocha-cljs itself Also in no way I’m expecting things to magically happen to make my life easier. I was simply sharing my experience, which may probably be my own fault. Please note that I have only gratitude, respect and admiration for your work.

markdingram · December 18, 2019, 12:38pm

I reiterate the thanks for creating this project & certainly didn’t expect such a prompt reply. If I can understand I’ll be more than happy to work on a PR.

I added a couple of screenshots from the working / failing dev console:

It appears the divergence is prior to the websocket code being sent across to the Browser REPL?

markdingram · December 18, 2019, 12:39pm

As an aside I tried with Firefox and see exactly the same behaviour. There was an exception in the Firefox log that wasn’t seen in Chromium, not sure if it could be relevant:

:cljs/err -> {:val "Copying jar:file:/home/mark/.m2/repository/org/clojure/google-closure-library/0.0-20170809-b9c14c6b/google-closure-library-0.0-20170809-b9c14c6b.jar!/goog/string/stringformat.js to out/goog/string/stringformat.js\n", :type :cljs/err}
Copying jar:file:/home/mark/.m2/repository/org/clojure/google-closure-library/0.0-20170809-b9c14c6b/google-closure-library-0.0-20170809-b9c14c6b.jar!/goog/string/stringformat.js to out/goog/string/stringformat.js

Exception in thread "Thread-11" java.net.SocketException: Broken pipe (Write failed)
        at java.base/java.net.SocketOutputStream.socketWrite0(Native Method)
        at java.base/java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:110)
        at java.base/java.net.SocketOutputStream.write(SocketOutputStream.java:150)
        at java.base/jdk.internal.reflect.GeneratedMethodAccessor12.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:167)
        at clojure.lang.Reflector.invokeInstanceMethod(Reflector.java:102)
        at cljs.repl.server$send_and_close.invokeStatic(server.clj:168)
        at cljs.repl.server$send_and_close.invoke(server.clj:144)
        at cljs.repl.browser$send_static.invokeStatic(browser.clj:205)
        at cljs.repl.browser$send_static.invoke(browser.clj:178)
        at cljs.repl.server$dispatch_request.invokeStatic(server.clj:191)
        at cljs.repl.server$dispatch_request.invoke(server.clj:182)
        at cljs.repl.server$handle_connection.invokeStatic(server.clj:199)
        at cljs.repl.server$handle_connection.invoke(server.clj:195)
        at cljs.repl.server$server_loop$fn__68.invoke(server.clj:209)
        at clojure.core$binding_conveyor_fn$fn__5754.invoke(core.clj:2030)
        at clojure.lang.AFn.run(AFn.java:22)
        at java.base/java.lang.Thread.run(Thread.java:834)
EVAL:  :cljs/quit
E]
Randomized with --seed 920322469

ERROR in browser-cljs (main.java:40)
Unexpected error executing kaocha-cljs test suite.
Exception: clojure.lang.ExceptionInfo: Kaocha ClojureScript client failed connecting back.
{:kaocha.testable/id :browser-cljs, :cljs/repl-env cljs.repl.browser/repl-env, :cljs/compiler-options {:verbose true, :closure-defines #:kaocha.type.cljs{log-level "DEBUG", root-log-level "DEBUG"}}}
 at kaocha.type.cljs$eval6729$fn__6731$fn__6745.invoke (cljs.clj:274)
    kaocha.type.cljs$queue_consumer.invokeStatic (cljs.clj:181)
    kaocha.type.cljs$queue_consumer.invoke (cljs.clj:173)
    kaocha.type.cljs$eval6729$fn__6731.invoke (cljs.clj:252)
    ...
    kaocha.testable$run.invokeStatic (testable.clj:119)

plexus · December 18, 2019, 2:12pm

I’m trying to reproduce it here. I tried it half a dozen times in Firefox and Chromium and couldn’t get it to fail…

Could you try the following: start chrome/chromium with --auto-open-devtools-for-tabs, then when kaocha runs go to the Network tab, find the request that failed, select it and take a screenshot of the full request details. (url, method, request and response headers, request body). Also take a screenshot of the list of requests.

Thanks!

markdingram · December 18, 2019, 2:38pm

Uploaded the screenshots / logs to

The first request with content {:repl nil, :type :ready, :content "ready", :order 1}: is successful, but the 2nd {:repl "Thread-129", :type :result, :content "{:status :success, :value \"\"}", :order 2}: times out after 10s

plexus · December 19, 2019, 9:56am

Thanks! It seems your screenshots are all truncated? The things I need to see should look something like this

Thanks!

markdingram · December 19, 2019, 12:43pm

I’ve hopefully uploaded better screenshots. Also I captured a network log file chromium-net.json which can be loaded into https://netlog-viewer.appspot.com - filtering this for “localhost:9000 URL_REQUEST” shows the failing request:

t=4031 [st=   0] +REQUEST_ALIVE  [dt=3625]
                  --> priority = "MEDIUM"
                  --> traffic_annotation = 101845102
                  --> url = "http://localhost:9000/"
t=4031 [st=   0]    NETWORK_DELEGATE_BEFORE_URL_REQUEST  [dt=0]
t=4031 [st=   0]   +URL_REQUEST_START_JOB  [dt=3625]
                    --> load_flags = 2 (BYPASS_CACHE)
                    --> method = "POST"
                    --> privacy_mode = 0
                    --> upload_id = "0"
                    --> url = "http://localhost:9000/"
t=4031 [st=   0]      NETWORK_DELEGATE_BEFORE_START_TRANSACTION  [dt=0]
t=4031 [st=   0]      HTTP_CACHE_GET_BACKEND  [dt=0]
                      --> net_error = -2 (ERR_FAILED)
t=4031 [st=   0]     +HTTP_STREAM_REQUEST  [dt=1]
t=4031 [st=   0]        HTTP_STREAM_JOB_CONTROLLER_BOUND
                        --> source_dependency = 712 (HTTP_STREAM_JOB_CONTROLLER)
t=4032 [st=   1]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                        --> source_dependency = 713 (HTTP_STREAM_JOB)
t=4032 [st=   1]     -HTTP_STREAM_REQUEST
t=4032 [st=   1]      UPLOAD_DATA_STREAM_INIT  [dt=0]
                      --> is_chunked = false
                      --> net_error = 0 (?)
                      --> total_size = 89
t=4032 [st=   1]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=1]
t=4033 [st=   2]        HTTP_TRANSACTION_SEND_REQUEST_HEADERS
                        --> POST / HTTP/1.1
                            Host: localhost:9000
                            Connection: keep-alive
                            Content-Length: 89
                            Pragma: no-cache
                            Cache-Control: no-cache
                            Origin: http://localhost:9000
                            User-Agent: Mozilla/5.0 (X11; Fedora; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.108 Safari/537.36
                            Content-Type: application/x-www-form-urlencoded;charset=UTF-8
                            Accept: */*
                            Sec-Fetch-Site: same-origin
                            Sec-Fetch-Mode: cors
                            Referer: http://localhost:9000/repl?xpc=%7B%22cn%22%3A%22bmPNRcpvMt%22%2C%22ppu%22%3A%22http%3A%2F%2Flocalhost%3A9000%2Frobots.txt%22%2C%22lpu%22%3A%22http%3A%2F%2Flocalhost%3A9000%2Frobots.txt%22%7D
                            Accept-Encoding: gzip, deflate, br
                            Accept-Language: en-GB,en-US;q=0.9,en;q=0.8
t=4033 [st=   2]        UPLOAD_DATA_STREAM_READ  [dt=0]
                        --> current_position = 0
t=4033 [st=   2]        HTTP_TRANSACTION_SEND_REQUEST_BODY
                        --> did_merge = true
                        --> is_chunked = false
                        --> length = 89
t=4033 [st=   2]     -HTTP_TRANSACTION_SEND_REQUEST
t=4033 [st=   2]     +HTTP_TRANSACTION_READ_HEADERS  [dt=3623]
t=4033 [st=   2]        HTTP_STREAM_PARSER_READ_HEADERS  [dt=3623]
                        --> net_error = -324 (ERR_EMPTY_RESPONSE)
t=7656 [st=3625]     -HTTP_TRANSACTION_READ_HEADERS
                      --> net_error = -324 (ERR_EMPTY_RESPONSE)
t=7656 [st=3625]   -URL_REQUEST_START_JOB
                    --> net_error = -324 (ERR_EMPTY_RESPONSE)
t=7656 [st=3625]    URL_REQUEST_DELEGATE_RESPONSE_STARTED  [dt=0]
t=7656 [st=3625] -REQUEST_ALIVE
                  --> net_error = -324 (ERR_EMPTY_RESPONSE)

Would you agree that this points toward the cljs repl startup?

markdingram · December 19, 2019, 12:47pm

A note on reproducing - this failure is seen fairly consistently for me only when there are no browser windows open when the test starts.

To set the Chromium flags on startup I added to /usr/lib64/chromium-browser/chromium-browser.sh

DEBUGGING_FLAGS=" --auto-open-devtools-for-tabs --log-net-log=/tmp/chromium-net.json --disk-cache-dir=/dev/null --disk-cache-size=1" exec -a "$0" "$HERE/chromium-browser" $DEBUGGING_FLAGS $CHROMIUM_DISTRO_FLAGS $CHROMIUM_FLASH_FLAGS "$@"

markdingram · December 19, 2019, 3:27pm

Possibly https://clojure.atlassian.net/projects/CLJS/issues/CLJS-1479

I’m investigating…

markdingram · December 20, 2019, 12:07am

I managed to piece together a solution in 2 parts -

cljs.repl.browser/setup calls maybe-browse-url whilst holding a lock. On Linux this falls through to xdg-open which blocks if the browser process isn’t already running.

I put a rough fix for this in a fork of kaocha-cljs (sorry forum is blocking github links?)
After this running local tests were 100% reliable - but still failing on Circle CI (using the circleci/clojure:openjdk-11-tools-deps-node-browsers image). Curiously rerunning the tests after SSHing into the failing Circle CI container worked.

A bit of headscratching led to Chrome’s --no-first-run argument. It appears that on first run chrome pops up a welcome page and ignores any URL sent to it, unless this argument is given…

markdingram · December 20, 2019, 9:41am

Upstream JIRA that should resolve point 1: https://clojure.atlassian.net/browse/CLJ-2493

Discussion here - add your upvotes if you visit!
https://ask.clojure.org/index.php/751/clojure-java-shell-sh-hangs-calling-xdg-open

plexus · December 20, 2019, 4:05pm

Thank you so much for further investigating this. I’m sure this will benefit several others. Hopefully the patch will make it into a ClojureScript release soon.

tkjone · December 23, 2019, 1:40pm

Hi! This reply is not directly related to kaocha, but have you see this post? https://betweentwoparens.com/clojurescript-test-setup

If not, it could help you continue to progress without kaocha and also can have kaocha added in at a later point. Good luck!

plexus · December 27, 2019, 10:44am

There’s a lot of accidental complexity in that post that goes away with Kaocha. Maybe someone can do a version of that post based on Kaocha (look at all the things I’m not doing)