run/streams.scala intermittently fails on Windows

[SethTisue]

seen at e.g. https://scala-ci.typesafe.com/view/scala-2.13.x/job/scala-2.13.x-integrate-windows/839/consoleText

!!  740 - run/streams.scala                         [output differs]
% diff Y:\jenkins\workspace\scala-2.13.x-integrate-windows\test\files\run\streams.check Y:\jenkins\workspace\scala-2.13.x-integrate-windows\test\files\run\streams-run.log--- streams.check
+++ streams-run.log
@@ -37,3 +37,48 @@
 705082704
-
-true
+java.lang.NullPointerException
+	at java.lang.reflect.Array.getLength(Native Method)
+	at scala.collection.IterableOnceOps.copyToArray(IterableOnce.scala:813)
+	at scala.collection.IterableOnceOps.copyToArray$(IterableOnce.scala:812)
+	at Test$.delayedEndpoint$Test$1(streams.scala:59)
+	at Test$delayedInit$body.apply(streams.scala:3)
+	at scala.Function0.apply$mcV$sp(Function0.scala:39)
+	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
+	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
+	at scala.App.$anonfun$main$1(App.scala:76)
+	at scala.App.$anonfun$main$1$adapted(App.scala:76)
+	at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:518)
+	at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:516)
+	at scala.collection.AbstractIterable.foreach(Iterable.scala:916)
+	at scala.App.main(App.scala:76)
+	at scala.App.main$(App.scala:74)
+	at Test$.main(streams.scala:3)
+	at Test.main(streams.scala)
+	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
+	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
+	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
+	at java.lang.reflect.Method.invoke(Method.java:498)
+	at scala.tools.partest.nest.Runner.$anonfun$execTestInProcess$2(Runner.scala:249)
+	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:62)
+	at scala.Console$.withOut(Console.scala:167)
+	at scala.tools.partest.nest.StreamCapture$.$anonfun$capturingOutErr$2(StreamCapture.scala:40)
+	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:62)
+	at scala.Console$.withErr(Console.scala:196)
+	at scala.tools.partest.nest.Runner.$anonfun$execTestInProcess$1(Runner.scala:245)
+	at scala.tools.partest.nest.Runner.run$2(Runner.scala:241)
+	at scala.tools.partest.nest.Runner.$anonfun$execTestInProcess$3(Runner.scala:268)
+	at scala.tools.partest.nest.Runner.execTestInProcess(Runner.scala:268)
+	at scala.tools.partest.nest.Runner.exec$1(Runner.scala:649)
+	at scala.tools.partest.nest.Runner.$anonfun$runRunTest$1(Runner.scala:651)
+	at scala.tools.partest.nest.Runner.$anonfun$runTestCommon$1(Runner.scala:551)
+	at scala.tools.partest.nest.Runner.runInContext(Runner.scala:435)
+	at scala.tools.partest.nest.Runner.runTestCommon(Runner.scala:548)
+	at scala.tools.partest.nest.Runner.runRunTest(Runner.scala:651)
+	at scala.tools.partest.nest.Runner.run(Runner.scala:640)
+	at scala.tools.partest.nest.AbstractRunner.liftedTree1$1(AbstractRunner.scala:313)
+	at scala.tools.partest.nest.AbstractRunner.runTest(AbstractRunner.scala:313)
+	at scala.tools.partest.nest.AbstractRunner.$anonfun$runTestsForFiles$2(AbstractRunner.scala:338)
+	at scala.tools.partest.package$$anon$2.call(package.scala:139)
+	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
+	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
+	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
+	at java.lang.Thread.run(Thread.java:745)

@NthPortal what do you make of this, could this be a real bug?

note that I'm not completely certain it never fails except on Windows, if anyone else has seen this on a non-Windows system, let us know

[SethTisue]

ping @NthPortal

[Jasper-M]

Some sort of Java Memory Model intricacy or bug?
Seems to me that the problem boils down to this:

object Test {
  private[this] var _arr: Array[Int] = null
  def arr() = _arr

  def main(args: Array[String]): Unit = {
    _arr = new Array[Int](100000)
    assert(arr() ne null) //fails
  }
}

Except with a whole bunch of extra indirection via DelayedInit. And the way it gets run by the test framework might also be relevant...

[som-snytt]

Also ScalaRunTime.array_length is inlined, which invokes java.lang.reflect.Array.getLength. Though on M5 :javap doesn't show it inlined. Maybe it was only recently made inline?

:javap -pv scala.collection.IterableOnceOps#copyToArray

In fact, git blame shows it was inlined in September.

[NthPortal]

@SethTisue oops, I missed this. Sorry!

For reference, the NPE appears to be thrown by this line.

// copies of the relevant lines
  val size = 100000
  val arr = new Array[Int](size)
  LazyList.from(1).take(size).copyToArray(arr, 0) // throws NPE sometimes?

@Jasper-M you think arr is somehow null in the call to copyToArray, despite being initialized? that would certainly be a fun thing to work around. Does the test code you pasted actually fail sometimes?

[Jasper-M]

@som-snytt you think arr is somehow null in the call to copyToArray, despite being initialized? that would certainly be a fun thing to work around. Does the test code you pasted actually fail sometimes?

I guess I'm supposed to come up with some kind of pun now...
Based on the stacktrace I would say that xs in xs.length in copyToArray is somehow null. So I assume that's because arr is null in the call to copyToArray. I don't think that test code would ever fail when you would run it as-is, or I would certainly hope so. But based on the evidence presented it appears that when you run something very similar through partest on Windows it does fail sometimes. But it's strange that it doesn't happen in other places or other tests where App is used.

Perhaps some cosmic ray hit the CPU of the CI machine at just the right spot...

edit: I see that it failed multiple times in exactly the same spot so we can probably rule out the cosmic rays.

[NthPortal]

do we just give up on App for this test, and have an explicit main?

[som-snytt]

I'll never use App in a test again...

It would be nice to know if it started to fail at a certain point and check JDK too, in case it's a JDK bug.

[SethTisue]

this is still failing about 1 out of every 5–10 runs at https://scala-ci.typesafe.com/job/scala-2.13.x-integrate-windows/

I don't consider it a blocker for 2.13.0, but I don't think we should back-burner it indefinitely, either — partly because the CI noise is annoying, but also because there may be a real bug here

would someone like to volunteer to dig into it further? (@NthPortal no worries if you don't have time, you've done a great deal)

[NthPortal]

I'll try to have a look this week

[szeiger]

Removing all the other test lines, I get this code in Test$:

A straight-forward getter. This is the only place where arr is read:

  public int[] arr();
    Code:
       0: getstatic     #82                 // Field arr:[I
       3: areturn

The actual App body:

  public final void delayedEndpoint$Test$1();
    Code:
       0: ldc           #84                 // int 100000
       2: putstatic     #79                 // Field size:I
       5: aload_0
       6: invokevirtual #86                 // Method size:()I

Create the array (https://docs.oracle.com/javase/specs/jvms/se7/html/jvms-6.html#jvms-6.5.newarray). Can throw exceptions but must never return null:

       9: newarray       int

And this is the only place where arr is written:

      11: putstatic     #82                 // Field arr:[I
      14: getstatic     #91                 // Field scala/package$.MODULE$:Lscala/package$;
      17: invokevirtual #95                 // Method scala/package$.LazyList:()Lscala/collection/immutable/LazyList$;
      20: iconst_1
      21: istore_3
      22: dup

What's with these strange null checks? if(receiver eq null) throw null? Why do we generate them?

      23: ifnonnull     28
      26: aconst_null
      27: athrow
      28: iload_3
      29: iconst_1
      30: invokevirtual #101                // Method scala/collection/immutable/LazyList$.from:(II)Lscala/collection/immutable/LazyList;
      33: aload_0
      34: invokevirtual #86                 // Method size:()I
      37: invokevirtual #107                // Method scala/collection/immutable/LazyList.take:(I)Lscala/collection/immutable/LazyList;

Reading arr again and storing it in slot 1 (followed by another, seemingly unnecessary null check for the receiver)

      40: aload_0
      41: invokevirtual #109                // Method arr:()[I
      44: iconst_0
      45: istore_2
      46: astore_1
      47: dup
      48: ifnonnull     53
      51: aconst_null
      52: athrow

Loading it back onto the stack and calling copyToArray:

      53: aload_1
      54: iload_2
      55: invokestatic  #115                // InterfaceMethod scala/collection/IterableOnceOps.copyToArray$:(Lscala/collection/IterableOnceOps;Ljava/lang/Object;I)I
      58: pop
      59: return

Here's the catch:

  private static final int[] arr;

The vals of the App's body become static final fields. According to https://docs.oracle.com/javase/specs/jls/se11/html/jls-8.html#jls-8.3.1.2:

A blank final class variable must be definitely assigned by a static initializer of the class in which it is declared, or a compile-time error occurs

I seem to remember a similar case about initialization in constructors but I don't recall the conclusion. According to the JLS "definitely (un)assigned" is defined in terms of lexical scope, i.e. a static final field must be assigned directly inside a static initializer, not in any method called from a static initializer, but that's exactly what we are doing.

I don't know why the results are inconsistent (it's all single-threaded, so it shouldn't be a race condition; does the optimizer take random guesses?) but setting arr via putstatic at that point in the code appears to be illegal, so it's not surprising that it's still seen as unassigned afterwards.