BuildInfo fails to write the same file twice

[lolgab]

It seems BuildInfo uses os.write when it should use os.write.over.

1 targets failed
integration.test.generatedBuildInfo java.nio.file.FileAlreadyExistsException: /Users/lorenzo/scala/snunit/out/integration/test/generatedBuildInfo.dest/BuildInfo.scala
    sun.nio.fs.UnixException.translateToIOException(UnixException.java:88)
    sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
    sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
    sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:214)
    java.nio.file.Files.newByteChannel(Files.java:361)
    os.write$.write(ReadWriteOps.scala:59)
    os.write$.apply(ReadWriteOps.scala:70)
    mill.contrib.buildinfo.BuildInfo.$anonfun$generatedBuildInfo$2(BuildInfo.scala:36)
    mill.define.Task$TraverseCtx.evaluate(Task.scala:376)

[lefou]

This is strange. The generateBuildInfo target should always work on a freshly created dest dir. Can you share some more context, Mill --version output, Your build file?

[ajrnz]

I've seen something like this when running tests. My was complaining that a file in the out/ director already exists ie

java.nio.file.FileAlreadyExistsException: /Users/ajr/dev/proj/out/proj/test/test.dest/out.json
	at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:94)
	at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)

I don't think it is an error with BuildInfo or my tests but rather that mill is sometimes failing to shutdown processes on Ctrl-C and thus when I run my tests with -w there is another copy being run in the background which is clashing. This can be seen with a ps ... | grep .... It is intermittent as the two processes don't always clash.

I've also seen GUI processes stay alive when I Ctrl-C in the mill proj.runMain ... terminal although it's hard to reproduce. This didn't happen before upgrading to 0.10.0 so it might be something to do with the new terminal code?

Sorry that is a bit vague but it happen very often.

I'm on MacOS x86

[lefou]

We should collect as much context as possible here. Two changes come to my mind that we made during 0.10 develoment, that may be related:

• We refactored the test runner
• We reworked the out/ directory layout and touched also the handling of <target>.dest/ dirs

Your both issues might be still unrelated though.

[ajrnz]

I'm pretty sure it's Ctrl-C related and when using -w

If I run:

package milltest

object MillTest extends App {
  var i = 0
  val pid = ProcessHandle.current().pid()
  val testDir = os.pwd / "test"
  os.makeDir.all(testDir)
  while(true) {
    println(s"running: $i")
    i += 1    
    os.remove(testDir / s"TestFile-$pid-${i-1}.txt")
    os.write.over(testDir / s"TestFile-$pid-$i.txt", "")
    Thread.sleep(100)
  }
}

via

mill -w milltest.run

And then Ctrl-C you can see the process still running in the background with ps and the file name keeps changing in the background.

This is under MacOS.

I hope this helps.

[lolgab]

I also have been experiencing some general instability, like this issue that I reported.
It also happened to me tha Mill executed a different command than the one I sent (which happened to be a production deploy on a dirty branch, but whatever 😄)
I didn't report it yet because it was hard to reproduce. It happened rarely.

[lolgab]

This touched how -w works by the way: #1645

[lefou]

Could also be some change in Ammonite or in how we use Ammonite, especially regarding caching. This hit use previously (in the very low versions). When Ammonite decides to use an older or incorrect cached version, any kind of strange behavior can be observed.

[lefou]

FTR, I tried to use -w with tests a lot but was not able to reproduce this issue.

[ajrnz]

What OS are you on? I get these problems on MacOS but that's the only place I run mill interactively

[lolgab]

The reproduction here works very well in my setup. You will not see the logs of the processes because the streams are disconnected but they are in the background doing work.

EDIT: When I say work I mean that the problem exists and I can see it thanks to the reproduction.

[lefou]

My env:

Mill Build Tool version 0.10.1
Java version: 11.0.14, vendor: Eclipse Adoptium, runtime: /opt/openjdk-bin-11.0.14_p9
Default locale: de_DE, platform encoding: UTF-8
OS name: "Linux", version: 5.15.23-gentoo-x86_64, arch: amd64

@lolgab Thanks for pointing it out. I'll try it.

[lefou]

The reproduction here works very well in my setup. You will not see the logs of the processes because the streams are disconnected but they are in the background doing work.

EDIT: When I say work I mean that the problem exists and I can see it thanks to the reproduction.

I can't not reproduce the OP issue, but I can see, that Mill is keeping the spawned test process alive after shutting down itself. This is something I though I've fixed when I implemented the sutdown hook in runSubprocess some years ago. 🤔

[lefou]

I strongly think, this is an issue with --watch in combination with explicit Mill abortion (^C). Looks like it is not properly propagated to the underlying Ammonite watch mechanism, so that the process started with --watch continues. In the example above, where a test main never stops programmatically, this results in a continued process. But it can also be observed with other tasks. E.g. I just now observed the following:

$ mill clean __.compile
...
$ mill -w __.compile
...
[681/2049]
^C
$ mill __.compile
// almost finished immediatly

So, instead of stopping compilation at around progress 681 of 2049, it continued compiling in the background.

I've not checked, but this could also result in the appearance of more than one running mill server process (out/mill-worker-*).

[ajrnz]

There definitely seems to be some sort of miscommunication from the server to the client regarding termination. For example if you write a program:

object MillTest extends App {
  (1 to 100000).foreach{ i =>
    println(i)
  }
}

in a mill-test project and run

mill mill-test.run > result.txt

the file result.txt is truncated. The same happens if you run it to the console. Running with -i does not have the problem.

[If you think this is unrelated I am happy to open it as its own issue]

[lihaoyi]

I've hit this reproducibly when I've had multiple Mill processes running, e.g. one in --watch in some background terminal I forgot about, and one in --watch in a foreground terminal. I wonder if that could be the case for others?

Mill doesn't have a formal concurrency model w.r.t. multiple Mill processes running over the same targets at the same time, so it makes sense it could misbehave.

[lefou]

We have a discussion about the concurrency topic here: #2820

We already synchronize concurrent task evaluations inside the same Mill process (#2980). We still need to implement it inter-process synchronization.

[lihaoyi]

Going to call this hopefully fixed by @alexarchambault 's work adding a coarse grained lock around the out folder