Possible problem when resizing the daemon registry

[theit]

Following the instructions in the readme, I tried to locally build mvnd, but without success. A JUnit test fails:

C:\Users\thoh\git\apache.org\maven-mvnd>mvn clean verify -Pnative
[INFO] Scanning for projects...
(...)
[INFO] ----------------< org.apache.maven.daemon:mvnd-common >-----------------
[INFO] Building Maven Daemon - Common 0.9.0-SNAPSHOT                     [6/10]
[INFO] --------------------------------[ jar ]---------------------------------
(...)
[INFO] --- maven-surefire-plugin:3.0.0-M5:test (default-test) @ mvnd-common ---
[INFO]
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.mvndaemon.mvnd.common.DaemonRegistryTest
[main] INFO org.mvndaemon.mvnd.common.DaemonRegistry - Resizing registry to 64 kb due to buffer overflow
[main] INFO org.mvndaemon.mvnd.common.DaemonRegistry - Resizing registry to 128 kb due to buffer overflow
[main] INFO org.mvndaemon.mvnd.common.DaemonRegistry - Resizing registry to 64 kb due to buffer underflow
[main] WARN org.mvndaemon.mvnd.common.DaemonRegistry - Invalid daemon registry info, trying to recover from this issue. If you keep getting this warning, try deleting the `registry.bin` file at [C:\Users\thoh\AppData\Local\Temp\reg5075242740053077541.data]
java.lang.IllegalStateException: Bad string size: 3072
        at org.mvndaemon.mvnd.common.DaemonRegistry.readString(DaemonRegistry.java:357)
        at org.mvndaemon.mvnd.common.DaemonRegistry.doUpdate(DaemonRegistry.java:225)
        at org.mvndaemon.mvnd.common.DaemonRegistry.read(DaemonRegistry.java:176)
        at org.mvndaemon.mvnd.common.DaemonRegistry.getAll(DaemonRegistry.java:114)
        at org.mvndaemon.mvnd.common.DaemonRegistryTest.testRecovery(DaemonRegistryTest.java:124)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)
(...)
[ERROR] Tests run: 3, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 0.508 s <<< FAILURE! - in org.mvndaemon.mvnd.common.DaemonRegistryTest
[ERROR] org.mvndaemon.mvnd.common.DaemonRegistryTest.testBigRegistry  Time elapsed: 0.475 s  <<< ERROR!
org.mvndaemon.mvnd.common.DaemonException: Exception while updating C:\Users\thoh\AppData\Local\Temp\reg15026837188086410214.data
        at org.mvndaemon.mvnd.common.DaemonRegistry.doUpdate(DaemonRegistry.java:285)
        at org.mvndaemon.mvnd.common.DaemonRegistry.update(DaemonRegistry.java:180)
        at org.mvndaemon.mvnd.common.DaemonRegistry.remove(DaemonRegistry.java:139)
        at org.mvndaemon.mvnd.common.DaemonRegistryTest.testBigRegistry(DaemonRegistryTest.java:88)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)
(...)
Caused by: java.io.IOException: Der Vorgang ist bei einer Datei mit einem geöffneten Bereich, der einem Benutzer zugeordnet ist, nicht anwendbar
        at java.base/sun.nio.ch.FileDispatcherImpl.truncate0(Native Method)
        at java.base/sun.nio.ch.FileDispatcherImpl.truncate(FileDispatcherImpl.java:90)
        at java.base/sun.nio.ch.FileChannelImpl.truncate(FileChannelImpl.java:437)
        at org.mvndaemon.mvnd.common.DaemonRegistry.doUpdate(DaemonRegistry.java:265)
        ... 71 more
(...)
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  18.284 s
[INFO] Finished at: 2022-09-29T09:13:52+02:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:3.0.0-M5:test (default-test) on project mvnd-common: There are test failures.
(...)

This happens with Maven 3.8.6 and GraalVM 22.2.0 and either building the master branch or the tagged version 0.8.1.

Checking out 0.8.0, I also see a stracktrace on the console, but the unit test doesn't fail and the build continues:

[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.mvndaemon.mvnd.common.DaemonRegistryTest
[main] WARN org.mvndaemon.mvnd.common.DaemonRegistry - Invalid daemon registry info, trying to recover from this issue. If you keep getting this warning, try deleting the `registry.bin` file at [C:\Users\thoh\AppData\Local\Temp\reg3037445246490135160.data]
java.lang.IllegalStateException: Bad string size: 3072
        at org.mvndaemon.mvnd.common.DaemonRegistry.readString(DaemonRegistry.java:313)
        at org.mvndaemon.mvnd.common.DaemonRegistry.doUpdate(DaemonRegistry.java:214)
        at org.mvndaemon.mvnd.common.DaemonRegistry.read(DaemonRegistry.java:165)
        at org.mvndaemon.mvnd.common.DaemonRegistry.getAll(DaemonRegistry.java:103)
        at org.mvndaemon.mvnd.common.DaemonRegistryTest.testRecovery(DaemonRegistryTest.java:81)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)
(...)
[INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.15 s - in org.mvndaemon.mvnd.common.DaemonRegistryTest

I then thought, let's have a look at the code in my Eclipse IDE and try to find out what's going on:
Running the unit test class inside Eclipse with Adoptium OpenJDK 17.0.4.1, I see the same error message, but the unit test itself is marked as being executed successfully:

[main] INFO org.mvndaemon.mvnd.common.DaemonRegistry - Resizing registry to 64 kb due to buffer overflow
[main] INFO org.mvndaemon.mvnd.common.DaemonRegistry - Resizing registry to 128 kb due to buffer overflow
[main] INFO org.mvndaemon.mvnd.common.DaemonRegistry - Resizing registry to 64 kb due to buffer underflow
[main] WARN org.mvndaemon.mvnd.common.DaemonRegistry - Invalid daemon registry info, trying to recover from this issue. If you keep getting this warning, try deleting the `registry.bin` file at [C:\Users\thoh\AppData\Local\Temp\reg7220429744484783348.data]
java.lang.IllegalStateException: Bad string size: 3072
	at org.mvndaemon.mvnd.common.DaemonRegistry.readString(DaemonRegistry.java:357)
	at org.mvndaemon.mvnd.common.DaemonRegistry.doUpdate(DaemonRegistry.java:225)
	at org.mvndaemon.mvnd.common.DaemonRegistry.read(DaemonRegistry.java:176)
	at org.mvndaemon.mvnd.common.DaemonRegistry.getAll(DaemonRegistry.java:114)
	at org.mvndaemon.mvnd.common.DaemonRegistryTest.testRecovery(DaemonRegistryTest.java:124)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)
(...)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:452)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:210)

Funny:
With IBM's Semeru variant 17.0.4.1 instead of the Adoptium runtime, the same error message appears, but then the test is marked as faulty...

Does someone have any idea what is causing this strange behaviour?

[ppalaga]

Does at least the version mix we use on GutHub actions for work for you? - ie. ./mvnw instead of your local maven installation, GraalVM 22.2.0 for Java 17 set in JAVA_HOME

[theit]

No, this gives me the same error.
I investigated a bit in the code trying to figure out at what part the exception occurs, and finally found a way out (workaround?) by explicitely triggering the garbage collector in DaemonRegistry.java:

--- a/common/src/main/java/org/mvndaemon/mvnd/common/DaemonRegistry.java
+++ b/common/src/main/java/org/mvndaemon/mvnd/common/DaemonRegistry.java
@@ -262,6 +262,7 @@ public class DaemonRegistry implements AutoCloseable {
                             LOGGER.info("Resizing registry to {} kb due to buffer underflow", (size / 1024));
                             l.release();
                             BufferHelper.closeDirectByteBuffer(buffer, LOGGER::debug);
+                            System.gc();
                             channel.truncate(size);
                             try {
                                 buffer = channel.map(FileChannel.MapMode.READ_WRITE, 0, size);

Reason:
You first release the file lock and then call a helper method to close the mapped byte buffer before truncating the file. The Javadoc for MappedByteBuffer states:

"A mapped byte buffer and the file mapping that it represents remain valid until the buffer itself is garbage-collected."

It seems that at least on my environment (Windows 10 x64 with the initially mentioned Java version(s)) this doesn't work as desired b/c the byte buffer still exists...

[gnodet]

That makes sense, could you create a PR for that please ?

[theit]

Yes, sure.