Flaky Ammonite test on windows

ckipp01 commented 4 years ago

Describe the bug I've been seeing the following fail on windows pretty consistently.

[info] Test run tests.RangeFormattingWhenPastingSuite finished: 0 failed, 0 ignored, 15 total, 71.291s
Error deleting C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.1.44086126562170075674.jar: java.nio.file.FileSystemException: C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.1.44086126562170075674.jar: The process cannot access the file because it is being used by another process.

Error deleting C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.1.42451691160055696164.jar: java.nio.file.FileSystemException: C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.1.42451691160055696164.jar: The process cannot access the file because it is being used by another process.

Error deleting C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.1.46551272268832771215.jar: java.nio.file.FileSystemException: C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.1.46551272268832771215.jar: The process cannot access the file because it is being used by another process.

Error deleting C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.1.41230435427312411412.jar: java.nio.file.FileSystemException: C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.1.41230435427312411412.jar: The process cannot access the file because it is being used by another process.

Error deleting C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.1.47523226631666151249.jar: java.nio.file.FileSystemException: C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.1.47523226631666151249.jar: The process cannot access the file because it is being used by another process.

Search terms CI, Ammonite

tgodzik commented 4 years ago

I think this is more likely connected to:

2020.06.01 02:13:31 INFO  Connected to Ammonite Build server v2.1.4
2020.06.01 02:13:41 INFO  time: indexed workspace in 1.3s
2020.06.01 02:13:41 INFO  compiling main.sc
2020.06.01 02:13:48 INFO  time: compiled main.sc in 7.29s
2020.06.01 02:13:48 INFO  tests.TestingServer#didSave
2020.06.01 02:13:50 INFO  compiling main.sc
2020.06.01 02:13:50 ERROR Error re-importing Ammonite build
java.nio.file.NoSuchFileException: D:\a\metals\metals\tests\unit\target\e2e\ammonite\hover\.ammonite\scala-2.12.11\amm-2.1.4\main\target\META-INF\semanticdb
    at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:85)
    at sun.nio.fs.WindowsException.asIOException(WindowsException.java:112)
    at sun.nio.fs.WindowsWatchService$Poller.implRegister(WindowsWatchService.java:366)
    at sun.nio.fs.AbstractPoller.processRequests(AbstractPoller.java:265)
    at sun.nio.fs.WindowsWatchService$Poller.run(WindowsWatchService.java:596)
    at java.lang.Thread.run(Thread.java:834)

No more data in the client stdin, exiting...

@alexarchambault any hints on what might be going on here?

alexarchambault commented 4 years ago

I don't think these two errors are connected. The one you're seeing, @tgodzik, looks like a race condition. Seems Ammonite is compiling something, so it wiped the corresponding semanticDBs. But indexing found the semanticDB before that, and the semanticDB must have been deleted right before it tried to access it. I'll have a closer look, I guess just waiting for compilation to complete after some didSave in the tests should prevent that from happening.

The messages you're seeing, @ckipp01, can be safely ignored. They're emitted by this line. It just means a temporary file couldn't be cleaned-up, but this shouldn't have consequences. If some tests fail later on, this is likely not connected to that.

tgodzik commented 4 years ago

I guess just waiting for compilation to complete after some didSave in the tests should prevent that from happening.

It looks like we are already doing that, that NoSuchFileException might also be not 100% related. :thinking:

alexarchambault commented 4 years ago

Maybe this is run before compilation completed. The output suggests that compilation of main.sc was still on-going.

tgodzik commented 4 years ago

It does seem like the compilation was not finished, although didSave does wait for it to finish. Maybe we could throw in another didSave afterwards. There might be some kind of a race condition between reimport and compilation?

tgodzik commented 4 years ago

Trying some things here: https://github.com/scalameta/metals/pull/1803

tgodzik commented 4 years ago

The tests seems to still be really flaky. We might just need to disable it on Windows.

alexarchambault commented 4 years ago

You could try to bump the Ammonite version to 2.1.4-6-2179b35, that includes https://github.com/lihaoyi/Ammonite/pull/1091. (That said, it's no big deal if flaky Ammonite tests are disabled on Windows…)

tgodzik commented 4 years ago

Thanks, I will check that out!

kpbochenek commented 4 years ago

Right now it happens only in LSP Integration Suite group, one stacktrace as example:

020.06.11 13:46:09 INFO  compiling main.sc
2020.06.11 13:46:09 WARN  File watching failed, indexes will not be updated.
java.nio.file.NoSuchFileException: /home/runner/work/metals/metals/tests/slow/target/e2e/ammonite/hover/.ammonite/scala-2.13.2/amm-2.1.4/main/target/META-INF/semanticdb
    at sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
    at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
    at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116)
    at sun.nio.fs.UnixFileAttributeViews$Basic.readAttributes(UnixFileAttributeViews.java:55)
    at sun.nio.fs.UnixFileSystemProvider.readAttributes(UnixFileSystemProvider.java:149)
    at sun.nio.fs.LinuxFileSystemProvider.readAttributes(LinuxFileSystemProvider.java:99)
    at java.nio.file.Files.readAttributes(Files.java:1763)
    at java.nio.file.FileTreeWalker.getAttributes(FileTreeWalker.java:219)
    at java.nio.file.FileTreeWalker.visit(FileTreeWalker.java:276)
    at java.nio.file.FileTreeWalker.walk(FileTreeWalker.java:322)
    at java.nio.file.Files.walkFileTree(Files.java:2716)
    at java.nio.file.Files.walkFileTree(Files.java:2796)
    at io.methvin.watcher.PathUtils.recursiveVisitFiles(PathUtils.java:86)
    at io.methvin.watcher.DirectoryWatcher.registerAll(DirectoryWatcher.java:327)
    at io.methvin.watcher.DirectoryWatcher.<init>(DirectoryWatcher.java:176)
    at io.methvin.watcher.DirectoryWatcher$Builder.build(DirectoryWatcher.java:117)
    at scala.meta.internal.metals.FileWatcher.startWatching(FileWatcher.scala:129)
    at scala.meta.internal.metals.FileWatcher.restart(FileWatcher.scala:108)
    at scala.meta.internal.metals.MetalsLanguageServer.$anonfun$indexWorkspace$5(MetalsLanguageServer.scala:1818)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
    at scala.meta.internal.metals.MetalsLanguageServer.timedThunk(MetalsLanguageServer.scala:1717)
    at scala.meta.internal.metals.MetalsLanguageServer.indexWorkspace(MetalsLanguageServer.scala:1817)
    at scala.meta.internal.metals.MetalsLanguageServer.$anonfun$profiledIndexWorkspace$2(MetalsLanguageServer.scala:1742)

cala.meta.internal.metals.MetalsLanguageServer.$anonfun$profiledIndexWorkspace$2(MetalsLanguageServer.scala:1742)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
    at scala.meta.internal.metals.MetalsLanguageServer.timedThunk(MetalsLanguageServer.scala:1717)
    at scala.meta.internal.metals.MetalsLanguageServer.$anonfun$profiledIndexWorkspace$1(MetalsLanguageServer.scala:1742)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
    at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:659)
    at scala.util.Success.$anonfun$map$1(Try.scala:255)
    at scala.util.Success.map(Try.scala:213)
    at scala.concurrent.Future.$anonfun$map$1(Future.scala:292)
    at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:33)
    at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:33)
    at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(Thread.java:834)

2020.06.11 13:46:11 INFO  tests.TestingServer#didSave
2020.06.11 13:46:11 INFO  time: indexed workspace in 1.82s
2020.06.11 13:46:12 INFO  compiling main.sc
2020.06.11 13:46:13 INFO  tests.TestingServer#didSave
[error] ==> X tests.feature.Ammonite213Suite.hover  26.045s munit.FailException: /home/runner/work/metals/metals/tests/unit/src/main/scala/tests/BaseAmmoniteSuite.scala:164 Obtained empty output!
[error] 163:      newHoverRes <- assertHoverAtPos("main.sc", 2, 18)
[error] 164:      _ = assertNoDiff(newHoverRes, expectedNewHoverRes)
[error] 165:

tgodzik commented 4 years ago

File watching is not an issue in this case really, it looks like when restarting the presentation compiler we don't pick up all the Scala files needed for hover, that's my guess. The support for Ammonite is based on the fact that normal files are being generated in .ammonite directory and then we can use them for hover.

Edit: Best would be to add some kind of additional debug that would figure out what was the cause for null we might do it it via debug logging inside the HoverProvider

ckipp01 commented 4 years ago

Closed by #2054

ckipp01 commented 4 years ago

Closed by #2054

False alarm... still having issues with it.

ckipp01 commented 4 years ago

Starting to see this flare up again.

Ignored error while deleting temporary file C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.2.0-4-4bd225e7968348512119006978.jar: java.nio.file.FileSystemException: C:\Users\RUNNER~1\AppData\Local\Temp\ammonite-2.2.0-4-4bd225e7968348512119006978.jar: The process cannot access the file because it is being used by another process.

https://github.com/scalameta/metals/pull/2147/checks?check_run_id=1256590992#step:5:6429

There was 3 failures in the steward prs that all point to the Ammonite suite on windows.

melekhove commented 1 year ago

Actual source of the error message is here: https://github.com/alexarchambault/ammonite-runner/blob/598b6a0dc92c9eedee02a70ed3ad887a960e279e/core/src/main/scala/ammrunner/AmmoniteFetcher.scala#L160-L169

melekhove commented 1 year ago

After some investigation I believe I've found the real reason.

ammonite-*.jar is an ammonite launcher used to start Ammonite BSP server.
it can't be deleted at the end of the test because the file is still open in the presentation compiler (as far as I remember it is an old well known feature/problem that jar files get cached in the compilation context, and there is no way to clear this cache somehow)

the file is loaded into the PC because this jar is reported as a part of the buildTarget/scalacOptions by the Ammonite BSP server Below is a fragment from the bsp.trace.json:

[Trace - 07:30:06 PM] Received response 'buildTarget/scalacOptions - (3)' in 567ms
Result: {
"items": [
{
  "target": {
    "uri": "file:///E:/projects/scala-metals/metals/target/e2e/ammonite-3.1.3/simple-script/main.sc"
  },
  "options": [
    "-Xsemanticdb",
    "-sourceroot",
    "E:\\projects\\scala-metals\\metals\\target\\e2e\\ammonite-3.1.3\\simple-script\\.ammonite\\scala-2.13.8\\amm-2.5.8\\main\\src",
    "-semanticdb-target",
    "E:\\projects\\scala-metals\\metals\\target\\e2e\\ammonite-3.1.3\\simple-script\\.ammonite\\scala-2.13.8\\amm-2.5.8\\main\\target"
  ],
  "classpath": [
    "file:///C:/Users/~/AppData/Local/Coursier/cache/v1/https/repo1.maven.org/maven2/io/circe/circe-core_3/0.14.2/circe-core_3-0.14.2.jar",
     ...
    "file:/C:/Users/~/AppData/Local/Temp/ammonite-2.5.88222932915468127855.jar",
    "file:/C:/Users/~/AppData/Local/Temp/rt16034659997756942240.jar"
  ],
  "classDirectory": "file:///E:/projects/scala-metals/metals/target/e2e/ammonite-3.1.3/simple-script/.ammonite/scala-2.13.8/amm-2.5.8/main/target/"
}
]
}

So, I think that classpath returned by Ammonite BSP server is not quite correct, it seems it contains much more items then necessary for target compilation. Theoretically, it is possible to filter just this entry, but that would be a dubious solution.

tgodzik commented 1 year ago

It would probably be best to filter that out inside AmmoniteBSP, but since it's only failing in tests I would honestly be ok with filtering on the Metals side also.

Thanks for investigation @melekhove !

scalameta / metals

Flaky Ammonite test on windows #1801