java.io.IOException: Got bad status ordinal in StatusSerializer.deserialize()

[sbrunk]

We're seeing JSEnvRPC$RunTerminatedException failures in a few tests while running them via scala-js-env-selenium. It seems to be caused by the following exception:

[error] Caused by: java.io.IOException: Got bad status ordinal: 758655357

I haven't been able to minimize the issue yet, but it's reproducable by checking out the branch to softwaremill/tapir#860 and then running sbt sttpClientJS/test (it only occurs when running one of these four tests).

Versions: Scala: 2.13.4, Scala.js: 1.3.1, sbt: 1.4.4

Full stack trace:

[error] org.scalajs.testing.common.RPCCore$ClosedException: org.scalajs.testing.adapter.JSEnvRPC$RunTerminatedException
[error]         at org.scalajs.testing.common.RPCCore.helpClose(RPCCore.scala:223)
[error]         at org.scalajs.testing.common.RPCCore.call(RPCCore.scala:164)
[error]         at org.scalajs.testing.common.RunMuxRPC.call(RunMuxRPC.scala:43)
[error]         at org.scalajs.testing.adapter.RunnerAdapter.done(RunnerAdapter.scala:58)
[error]         at sbt.Defaults$.$anonfun$allTestGroupsTask$11(Defaults.scala:1230)
[error]         at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:238)
[error]         at scala.collection.immutable.Map$Map1.foreach(Map.scala:128)
[error]         at scala.collection.TraversableLike.map(TraversableLike.scala:238)
[error]         at scala.collection.TraversableLike.map$(TraversableLike.scala:231)
[error]         at scala.collection.AbstractTraversable.map(Traversable.scala:108)
[error]         at sbt.Defaults$.$anonfun$allTestGroupsTask$5(Defaults.scala:1228)
[error]         at scala.Function1.$anonfun$compose$1(Function1.scala:49)
[error]         at sbt.internal.util.$tilde$greater.$anonfun$$u2219$1(TypeFunctions.scala:62)
[error]         at sbt.std.Transform$$anon$4.work(Transform.scala:67)
[error]         at sbt.Execute.$anonfun$submit$2(Execute.scala:281)
[error]         at sbt.internal.util.ErrorHandling$.wideConvert(ErrorHandling.scala:19)
[error]         at sbt.Execute.work(Execute.scala:290)
[error]         at sbt.Execute.$anonfun$submit$1(Execute.scala:281)
[error]         at sbt.ConcurrentRestrictions$$anon$4.$anonfun$submitValid$1(ConcurrentRestrictions.scala:178)
[error]         at sbt.CompletionService$$anon$2.call(CompletionService.scala:37)
[error]         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[error]         at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
[error]         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[error]         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[error]         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[error]         at java.base/java.lang.Thread.run(Thread.java:834)
[error] Caused by: org.scalajs.testing.adapter.JSEnvRPC$RunTerminatedException
[error]         at org.scalajs.testing.adapter.JSEnvRPC.$anonfun$new$1(JSEnvRPC.scala:38)
[error]         at org.scalajs.testing.adapter.JSEnvRPC.$anonfun$new$1$adapted(JSEnvRPC.scala:38)
[error]         at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
[error]         at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1426)
[error]         at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
[error]         at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
[error]         at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
[error]         at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
[error]         at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
[error] Caused by: java.io.IOException: Got bad status ordinal: 758655357
[error]         at org.scalajs.testing.common.Serializer$StatusSerializer$.deserialize(Serializer.scala:320)
[error]         at org.scalajs.testing.common.Serializer$StatusSerializer$.deserialize(Serializer.scala:313)
[error]         at org.scalajs.testing.common.Serializer$DeserializeState$.read$extension(Serializer.scala:37)
[error]         at org.scalajs.testing.common.Serializer$EventSerializer$$anon$6.<init>(Serializer.scala:352)
[error]         at org.scalajs.testing.common.Serializer$EventSerializer$.deserialize(Serializer.scala:348)
[error]         at org.scalajs.testing.common.Serializer$EventSerializer$.deserialize(Serializer.scala:338)
[error]         at org.scalajs.testing.common.Serializer$DeserializeState$.read$extension(Serializer.scala:37)
[error]         at org.scalajs.testing.common.RunMux$$anon$1.deserialize(RunMux.scala:28)
[error]         at org.scalajs.testing.common.RunMux$$anon$1.deserialize(RunMux.scala:21)
[error]         at org.scalajs.testing.common.Serializer$.deserialize(Serializer.scala:47)
[error]         at org.scalajs.testing.common.RPCCore.$anonfun$handleMessage$1(RPCCore.scala:115)
[error]         at org.scalajs.testing.common.RPCCore.$anonfun$handleMessage$1$adapted(RPCCore.scala:56)
[error]         at org.scalajs.testing.common.Serializer$.withInputStream(Serializer.scala:60)
[error]         at org.scalajs.testing.common.RPCCore.handleMessage(RPCCore.scala:56)
[error]         at org.scalajs.testing.adapter.JSEnvRPC.$anonfun$run$1(JSEnvRPC.scala:25)
[error]         at org.scalajs.testing.adapter.JSEnvRPC.$anonfun$run$1$adapted(JSEnvRPC.scala:25)
[error]         at org.scalajs.jsenv.selenium.SeleniumComRun.receivedMessage(SeleniumRun.scala:91)
[error]         at org.scalajs.jsenv.selenium.SeleniumRun.$anonfun$fetchAndProcess$3(SeleniumRun.scala:59)
[error]         at org.scalajs.jsenv.selenium.SeleniumRun.$anonfun$fetchAndProcess$3$adapted(SeleniumRun.scala:59)
[error]         at org.scalajs.jsenv.selenium.SeleniumRun$$anon$1.accept(SeleniumRun.scala:191)
[error]         at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
[error]         at org.scalajs.jsenv.selenium.SeleniumRun.fetchAndProcess(SeleniumRun.scala:59)
[error]         at org.scalajs.jsenv.selenium.SeleniumRun.$anonfun$handler$1(SeleniumRun.scala:37)
[error]         at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
[error]         at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:659)
[error]         at scala.util.Success.$anonfun$map$1(Try.scala:255)
[error]         at scala.util.Success.map(Try.scala:213)
[error]         at scala.concurrent.Future.$anonfun$map$1(Future.scala:292)
[error]         at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:33)
[error]         at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:33)
[error]         at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
[error]         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[error]         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[error]         at java.base/java.lang.Thread.run(Thread.java:834)

[gzm0]

FTR: The testing framework in question is Scalatest.

[gzm0]

@sbrunk what browser (which Selenium Capabilities) is this occurring with?

[gzm0]

From the top of my head, I have two theories why this might be happening:

• The JS / JVM side do not agree on the type/serialization format of a message. Unrelated data is decoded as Status. If this is the case, it is most likely in a case where something in the test fails (because these codepaths are much less well tested).
• The selenium driver / browser combination alters the encoding of the strings as they get passed through to the JVM side (e.g. replace bad surrogate pairs with placeholder characters).

[sbrunk]

Thanks for the pointers @gzm0. The browser is Chrome 87 using the following settings:

jsEnv in Test := {
  val debugging = false // set to true to help debugging
  System.setProperty("webdriver.chrome.driver", "target/chromedriver")
  new org.scalajs.jsenv.selenium.SeleniumJSEnv(
    {
      val options = new org.openqa.selenium.chrome.ChromeOptions()
      val args = Seq(
        "auto-open-devtools-for-tabs", // devtools needs to be open to capture network requests
        "no-sandbox",
        "allow-file-access-from-files" // change the origin header from 'null' to 'file'
      ) ++ (if (debugging) Seq.empty else Seq("headless"))
      options.addArguments(args: _*)
      val capabilities =
        org.openqa.selenium.remote.DesiredCapabilities.chrome()
      capabilities.setCapability(
        org.openqa.selenium.chrome.ChromeOptions.CAPABILITY,
        options
      )
      capabilities
    },
    org.scalajs.jsenv.selenium.SeleniumJSEnv
      .Config()
      .withKeepAlive(debugging)
  )
}

/cc @adamw

[gzm0]

Just to be certain: Does his problem still happen if you remove all the arguments to the chrome driver?

[gzm0]

Potentially related: /issues/105

[sbrunk]

@gzm0 yes, setting

jsEnv in Test := {
  new org.scalajs.jsenv.selenium.SeleniumJSEnv(new org.openqa.selenium.chrome.ChromeOptions())
}

still exhibits the same behavior. I'll try to set it up with Firefox for comparison.

[gzm0]

e.g. replace bad surrogate pairs with placeholder characters

It seems that our serialization only passes through ASCII characters. So this shouldn't be a problem. Now, maybe null bytes are a problem for certain drivers.

[sbrunk]

The tests pass without issues with Firefox/geckodriver using the default settings:

jsEnv := new org.scalajs.jsenv.selenium.SeleniumJSEnv(new org.openqa.selenium.firefox.FirefoxOptions())

So the issue seems to be chrome related indeed.

[adamw]

@sbrunk I'm fine with using firefox instead of chrome, if that would solve the problem, as long as the binaries are automatically downloaded and works on macos/linux :)

[gzm0]

I am transferring this to scala-js-env-selenium.

[gzm0]

Given what I have just found out about #105 (chrome doesn't handle messages containing 0x7F), this is very likely a dupe.

[gzm0]

@sbrunk this should be fixed with chrome 89 (no update to scala-js-env-selenium is required).

[sbrunk]

@gzm0 thanks for the update. I'll try to confirm that the tapir tests affected by this pass on chrome as soon as chromedriver 89 is available.

[adamw]

@sbrunk I think chromedriver 89 is now available? if you could verify this with tapir, it would be great :)

[sbrunk]

@adamw I just checked and I can confirm that the error does not occur anymore with Chrome 89. So I guess this issue can be closed. Thanks @gzm0 for getting to the root cause.