Bloop: Indicate cause of failure when execution is unsuccessful

[tindzk]

While debugging some local test failures (https://github.com/tindzk/seed/pull/31), we noticed that Bloop does not report any errors to stderr when the Node.js process could not be started.

However, when passing in --verbose, the following stack trace is visible:

[...]
[D] Emitter (write output): 47533 us
Generated JavaScript file '/tmp/seed1566034107928575769/example-paradise-platform/build/example.js'
Jul 25, 2019 10:17:33 AM com.zaxxer.nuprocess.linux.LinuxProcess start
WARNING: Failed to start process
java.io.IOException: error=2, No such file or directory
        at com.zaxxer.nuprocess.internal.LibJava8.Java_java_lang_UNIXProcess_forkAndExec(Native Method)
        at com.zaxxer.nuprocess.linux.LinuxProcess.start(LinuxProcess.java:109)
        at com.zaxxer.nuprocess.linux.LinProcessFactory.createProcess(LinProcessFactory.java:40)
        at com.zaxxer.nuprocess.NuProcessBuilder.start(NuProcessBuilder.java:266)
        at bloop.exec.Forker$.$anonfun$run$2(Forker.scala:175)
        at monix.eval.internal.TaskRunLoop$.monix$eval$internal$TaskRunLoop$$loop$1(TaskRunLoop.scala:187)
        at monix.eval.internal.TaskRunLoop$RestartCallback$1.onSuccess(TaskRunLoop.scala:119)
        at monix.eval.Task$.$anonfun$forkedUnit$2(Task.scala:1463)
        at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1402)
        at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
        at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
        at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
        at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)

[D] Forked process exited with code: -2147483648
[D] Process 0 exited with code: -2147483648
[D] Elapsed: 525.434596 ms

[jvican]

Thanks for reporting Tim, I'm marking as help wanted, I'd appreciate if someone can figure out why we're swallowing this exception and send a PR to fix this.

[tindzk]

Another error that gets swallowed is when running a JavaScript test module without JSDOM installed. When I ran bloop test <module>-test --verbose, the following stack trace was printed:

[D] Starting process: node
[D] Elapsed: 12791.795639 ms
[T] java.lang.reflect.InvocationTargetException
[T]     sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[T]     sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[T]     sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[T]     java.lang.reflect.Method.invoke(Method.java:498)
[T]     bloop.engine.tasks.toolchains.ScalaJsToolchain.discoverTestFrameworks(ScalaJsToolchain.scala:94)
[T]     bloop.engine.tasks.TestTask$.$anonfun$discoverTestFrameworks$3(TestTask.scala:184)
[T]     monix.eval.Task.$anonfun$map$1(Task.scala:407)
[T]     monix.eval.internal.TaskRunLoop$.monix$eval$internal$TaskRunLoop$$loop$1(TaskRunLoop.scala:176)
[T]     monix.eval.internal.TaskRunLoop$RestartCallback$1.onSuccess(TaskRunLoop.scala:119)
[T]     monix.eval.Task$.$anonfun$forkedUnit$2(Task.scala:1463)
[T]     java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1402)
[T]     java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
[T]     java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
[T]     java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
[T]     java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)
[T] Caused by: org.scalajs.jsenv.ExternalJSEnv$NonZeroExitException: Node.js with JSDOM exited with code 1
[T]     org.scalajs.jsenv.ExternalJSEnv$AbstractExtRunner.waitForVM(ExternalJSEnv.scala:114)
[T]     org.scalajs.jsenv.ExternalJSEnv$AsyncExtRunner$$anon$1.$anonfun$run$2(ExternalJSEnv.scala:179)
[T]     scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
[T]     scala.util.Try$.apply(Try.scala:213)
[T]     org.scalajs.jsenv.ExternalJSEnv$AsyncExtRunner$$anon$1.run(ExternalJSEnv.scala:179)

[kietay]

Hey @jvican I'm interested in investigating this one and trying to make a fix. I'm totally new to contributing to open source but have been working with scala for a couple years now so should be able to figure out what to do.

[kietay]

So I had a look and as far as I can see this is the expected behaviour, in BloopLogger we have:

 @scala.annotation.tailrec
  private def trace(prefix: String, exception: Throwable): Unit = {
    if (isVerbose) {
      print(prefix + exception.toString, printTrace)
      exception.getStackTrace.foreach(ste => print("\t" + ste.toString, printTrace))

      val cause = exception.getCause
      if (cause != null) trace("Caused by: ", cause)
    }
  }

Which seems to explain why verbose has to be on to get the stack trace.

Let me know if I'm way off the mark, if not I'm happy to send the PR to change this!

[jvican]

Hey @KieranCTaylor, happy to see you're interested in contributing! trace never prints exceptions to users intentionally. My suggestion to address this issue is to modify the part that runs the application/forks the running process and make sure that if there's an exception thrown it's logged manually via logger.error.

[kietay]

Hey @jvican I just had another look at this now.

I'm not sure what you mean by trace not printing exceptions intentionally, as far as I can see that is the intended action when verbose is on. I feel like this has to be the cause of the second example where it is being logged out as [T]. Again apologies if I am missing something obvious.

As for the first example where it's coming out as a debug message, I can't actually find where this is being output. I thought at first maybe it was in this pattern matcher in Forker:

case t: ioException =>
                logger.debug(s"Error from input gobbler: ${t.getMessage()}")
                logger.trace(t)
                // Rethrow so that Monix cancels future scheduling of the same task
                throw t

but if that were the case it should be prefixed by the input gobbler message.

Sorry I couldn't be more help and thank you for your guidance. If there's some other pointers I'd be happy to keep looking.

[jvican]

I'm not sure what you mean by trace not printing exceptions intentionally

I meant by default, which means verbose is not enabled.

In the code snippet you quote, could we perhaps make logger.debug and logger.trace be a logger.error with an explicit error message? I'm happy to give you more guidance over Gitter, I'm happy to schedule a chat too.

As for the first example where it's coming out as a debug message

Do you mean this?

[D] Emitter (write output): 47533 us

[kietay]

@jvican OK perfect I will drop you a message on gitter