Native and JVM builds: switch off the JEP 498 sun.misc.Unsafe warning at its source (Windows data corruption)

docs/modules/ROOT/pages/how-to/logs.adoc

@@ -43,7 +43,7 @@ export ARCADEDB_LOG_CONSOLE=0   # log to the file only (also on Linux and macOS)
 
 A `java.util.logging.config.file` that you set yourself (see below) replaces all of this: its handlers decide where the log goes.
 
-Log lines are not the only text the runtime writes through that handle: a warning a library prints, or a printed stack trace, goes to Java's `System.out` or `System.err`, and the runtime's own warnings go to a copy of `System.err` that `System.setErr` does not change. One of them is the warning that the runtime prints once, when the first vector index is reopened (`A terminally deprecated method in sun.misc.Unsafe has been called`, from the `jvector` library). In the `arcadedb-jvm` package, with the console off (the default on Windows, or `ARCADEDB_LOG_CONSOLE=0`), the package therefore points all three at `arcadedb-stdio.log` in the log directory, a file that it opens itself, right after the JVM starts. The runtime's own start-up warning (`WARNING: Using incubator modules: jdk.incubator.vector`) is printed while the JVM is created, before the package can do this, and still goes to the stderr of your process. With `ARCADEDB_LOG_CONSOLE=1` on Windows, `System.out` and `System.err` keep the runtime's handle, so the risk above stays: do not redirect fd 1 or 2 after the first database is opened.
+Log lines are not the only text the runtime writes through that handle: a warning a library prints, or a printed stack trace, goes to Java's `System.out` or `System.err`, and the runtime's own warnings go to a copy of `System.err` that `System.setErr` does not change. One of them is the warning that the runtime prints once, when the first vector index is reopened (`A terminally deprecated method in sun.misc.Unsafe has been called`, from the `jvector` library; JEP 498). Neither package lets that warning appear: the `arcadedb-jvm` package starts the JVM with `--sun-misc-unsafe-memory-access=allow` (a value of your own in `jvm_args` or `ARCADEDB_JVM_ARGS` wins), and the native image of the `arcadedb` package is built with the same option, which is fixed in the image and cannot be changed at run time. In the `arcadedb-jvm` package, for any other text of this kind, with the console off (the default on Windows, or `ARCADEDB_LOG_CONSOLE=0`), the package therefore points all three at `arcadedb-stdio.log` in the log directory, a file that it opens itself, right after the JVM starts. The runtime's own start-up warning (`WARNING: Using incubator modules: jdk.incubator.vector`) is printed while the JVM is created, before the package can do this, and still goes to the stderr of your process. With `ARCADEDB_LOG_CONSOLE=1` on Windows, `System.out` and `System.err` keep the runtime's handle, so the risk above stays: do not redirect fd 1 or 2 after the first database is opened.
 
 The packages themselves never print to the console on Windows: the glue code of the native build logs through the same engine log instead of writing to stderr.
 

native/scripts/build-image.sh

@@ -43,6 +43,9 @@ if [ "$EXT" = dll ]; then
         dependency:build-classpath -Dmdep.outputFile=target/runtime.cp >> "$OUT/build.log" 2>&1
     echo "native-image -cp target/arcadedb-native-lib-0.0.1.jar;$(tr -d '\r\n' < target/runtime.cp) --shared" >> "$OUT/build.log"
 fi
+# native-image.properties in the glue jar also carries JavaArgs = -Dsun.misc.unsafe.memory.access=allow for the builder's JVM (JEP 498: the image
+# would print the sun.misc.Unsafe warning that jvector causes on every vector index reopen, into a database file on Windows). The build log does not
+# show a JavaArgs line; tests/test_log_redirect.py is the gate that catches a lost one.
 # the jvector force-inline filters (native-image.properties in the glue jar) must be picked up: the build output lists the option and its origin (Windows prints the path with backslashes)
 grep -a -E -q 'PriorityForceInline. \(origin\(s\): .META-INF.native-image.org\.humemai.arcadedb-native-lib.native-image\.properties' "$OUT/build.log" ||
     {

native/src/main/resources/META-INF/native-image/org.humemai/arcadedb-native-lib/native-image.properties

@@ -7,3 +7,11 @@
 # The JDK's XML parser builds its error messages (JAXP00010001, entity limits and every syntax error) from this bundle; without it in the image a parse error
 # reads "Could not load any resource bundle by ...XMLMessages" and the entity-limit code is lost (test_native_xml_limits.py).
 Args = -H:PriorityForceInline=io.github.jbellis.jvector.vector.ArrayVectorFloat.length,io.github.jbellis.jvector.vector.ArrayVectorFloat.get,io.github.jbellis.jvector.vector.VectorUtil.squareL2Distance,io.github.jbellis.jvector.vector.VectorUtil.dotProduct,io.github.jbellis.jvector.vector.VectorUtil.cosine,io.github.jbellis.jvector.vector.DefaultVectorUtilSupport.squareDistance,io.github.jbellis.jvector.vector.DefaultVectorUtilSupport.squareDistanceUnrolled,io.github.jbellis.jvector.vector.DefaultVectorUtilSupport.dotProduct,io.github.jbellis.jvector.vector.DefaultVectorUtilSupport.cosine -H:IncludeResourceBundles=com.sun.org.apache.xerces.internal.impl.msg.XMLMessages
+# JEP 498 (JDK 24 and later): the first call of a sun.misc.Unsafe memory method prints "A terminally deprecated method in sun.misc.Unsafe has been called"
+# (four lines) to System.initialErr, and jvector's SimpleMappedReader$Supplier makes that call (Unsafe.invokeCleaner) when a vector index is reopened.
+# The image writes the text to the stderr handle the runtime cached at start-up: on Windows a database file opened after the host's dup2 onto fd 2 can
+# own that handle value and got the four lines (release run 40291551544, a .lsmvecidx file), on Linux the text reaches the host's redirect target.
+# sun.misc.Unsafe keeps its option (MemoryAccessOption, from --sun-misc-unsafe-memory-access=allow) in a static final that the image builder folds into
+# the image, so it is set for the builder's JVM here (JavaArgs); -Dsun.misc.unsafe.memory.access=allow as an isolate argument at run time does nothing.
+# tests/test_log_redirect.py fails on the native build when the text appears again.
+JavaArgs = -Dsun.misc.unsafe.memory.access=allow

src/arcadedb/jvm.py

@@ -854,6 +854,15 @@ def _build_jvm_args(
     if not any(arg.startswith("--enable-native-access") for arg in merged_args):
         merged_args.append("--enable-native-access=ALL-UNNAMED")
 
+    # JEP 498 (JDK 24 and later): the first call of a sun.misc.Unsafe memory method prints a four-line warning to System.initialErr.
+    # jvector causes it when it unmaps a graph file on the first reopen of a vector index, and a user cannot change jvector. "allow"
+    # (the JEP 471 option) switches the warning off at its source; a value in jvm_args or ARCADEDB_JVM_ARGS wins. The native build sets
+    # the same option when it builds the image (native/scripts/build-image.sh).
+    if not any(
+        arg.startswith("--sun-misc-unsafe-memory-access") for arg in merged_args
+    ):
+        merged_args.append("--sun-misc-unsafe-memory-access=allow")
+
     # Force UTF-8 regardless of OS locale to avoid silent encoding mismatches
     if not any(arg.startswith("-Dfile.encoding=") for arg in merged_args):
         merged_args.append("-Dfile.encoding=UTF8")

tests/test_jvm_args.py

@@ -53,6 +53,22 @@ def test_custom_jvm_args_merging():
         assert "-XX:+UseCompactObjectHeaders" in args
 
 
+def test_unsafe_memory_access_warning_is_off_by_default_and_can_be_overridden():
+    """JEP 498: ``allow`` keeps the runtime from printing its sun.misc.Unsafe warning (jvector causes it); a caller's value wins."""
+    allow = "--sun-misc-unsafe-memory-access=allow"
+    with patch.dict(os.environ, {}, clear=True):
+        args = _build_jvm_args(heap_size="4g", disable_xml_limits=True, jvm_args=None)
+        assert args.count(allow) == 1
+    with patch.dict(
+        os.environ,
+        {"ARCADEDB_JVM_ARGS": "--sun-misc-unsafe-memory-access=warn"},
+        clear=True,
+    ):
+        args = _build_jvm_args(heap_size="4g", disable_xml_limits=True, jvm_args=None)
+        assert "--sun-misc-unsafe-memory-access=warn" in args
+        assert allow not in args
+
+
 def test_polyglot_engine_default_can_be_overridden():
     """The polyglot engine is off by default and ``jvm_args`` or the env var turn it on.
 

tests/test_log_redirect.py

@@ -17,6 +17,14 @@
   ``System.out`` and ``System.err`` alone left it on the cached handle. (A canary file that took over the stale handle's value
   after the host's ``dup2`` held exactly these four lines.)
 
+The runtime's warning is also switched off at its source on both builds, so that no stream has it to write: the JVM build starts with
+``--sun-misc-unsafe-memory-access=allow`` (a default of ``jvm._build_jvm_args``; a caller's own value wins), and the native image is
+built with ``-Dsun.misc.unsafe.memory.access=allow`` for its builder (``JavaArgs`` in the glue jar's ``native-image.properties``;
+the image keeps the value as a constant, a ``-D`` at run time does nothing). The native image prints the same four lines to the
+cached stderr handle otherwise (dev1 release run 40291551544, Windows: ``db0\\Doc_0_485397029700.4.262144.v0.lsmvecidx`` started with
+them; on Linux the same text reaches the redirect target). The tests below check that the text is on no stream and in no file on both
+builds, and the JVM build also runs once with the option set back to ``warn`` to keep the ``System.initialErr`` redirect tested.
+
 The redirect tests run on every platform and on both builds (the first fix is shared; the second is the JVM build's, see below):
 on POSIX writes go to fd 1 and 2 by number, so a redirect is followed and the default passes trivially there, and on Windows it is
 the real check. The JVM build's console-off test also fails on POSIX without the second fix, because the Java probes below then go
@@ -190,10 +198,12 @@ def probe(step):
 """
 
 
-def _run(tmp_path, mode, console=None, repeats=REPEATS):
+def _run(tmp_path, mode, console=None, repeats=REPEATS, jvm_args=None):
     """Run CHILD in a fresh process. Returns the result dict, the process, the data and log directories, the redirect target's
-    text and the text of ``arcadedb-stdio.log`` (empty when there is none), in a namespace.
+    text and the text of ``arcadedb-stdio.log`` (empty when there is none), in a namespace. ``jvm_args`` is the child's
+    ``ARCADEDB_JVM_ARGS`` (the JVM build only).
     """
+    tmp_path.mkdir(exist_ok=True)
     data_dir = tmp_path / "data"
     data_dir.mkdir()
     log_dir = tmp_path / "log"
@@ -205,6 +215,8 @@ def _run(tmp_path, mode, console=None, repeats=REPEATS):
         if k not in ("ARCADEDB_LOG_CONSOLE", "ARCADEDB_LOG_DIR")
     }
     env["ARCADEDB_LOG_DIR"] = str(log_dir)
+    if jvm_args is not None:
+        env["ARCADEDB_JVM_ARGS"] = jvm_args
     if console is not None:
         env["ARCADEDB_LOG_CONSOLE"] = console
     proc = subprocess.run(  # nosec B603 - fixed argument list, no shell
@@ -286,11 +298,26 @@ def test_redirect_with_the_console_off_sends_nothing_to_the_redirect_target(tmp_
     # every probe, from both streams, is in the file the library owns (and nowhere else); the native build has none
     assert run.stdio.count(PROBE) == 2 * run.result["probes"], run.stdio[:500]
     assert run.stdio.count(b" out ") == run.stdio.count(b" err ")
+    # the runtime's JEP 498 warning is off at its source on both builds: it is on no stream (the redirect target would have it on
+    # Linux, a database file on Windows). The JVM child forced the trigger; the native one reaches it at the first reopen.
+    assert UNSAFE_WARNING not in run.sink, run.sink[:500]
+    assert UNSAFE_WARNING not in run.stdio, run.stdio[:500]
     if JVM:
-        assert UNSAFE_WARNING not in run.sink, run.sink[:500]
-        # the runtime's own warning is printed to System.initialErr, which setErr does not reach: it is there too
         assert run.result["unsafe"], UNSAFE_TRIGGER_FAILED
-        assert UNSAFE_WARNING in run.stdio, run.stdio[:500]
+        # with the option back to warn the runtime prints it to System.initialErr, which setErr does not reach: the redirect to
+        # arcadedb-stdio.log has to catch it there, and it must still be in no database file
+        warned = _run(
+            tmp_path / "warn",
+            "redirect",
+            console="0",
+            repeats=1,
+            jvm_args="--sun-misc-unsafe-memory-access=warn",
+        )
+        assert warned.result == warned.expected
+        assert warned.result["unsafe"], UNSAFE_TRIGGER_FAILED
+        assert UNSAFE_WARNING not in warned.sink, warned.sink[:500]
+        assert UNSAFE_WARNING in warned.stdio, warned.stdio[:500]
+        assert _stray_text_in_files(warned.data_dir) == []
 
 
 def test_console_log_can_be_turned_on(tmp_path):
@@ -302,6 +329,7 @@ def test_console_log_can_be_turned_on(tmp_path):
     assert LOG_LINE.search(console), console[:500]
     # the runtime keeps its own streams with the console on: the probes are on the console, there is no stdio file
     assert console.count(PROBE) == 2 * run.result["probes"], console[:500]
+    assert UNSAFE_WARNING not in console, console[:500]
     assert run.stdio == b""
     assert _stray_text_in_files(run.data_dir) == []
     assert LOG_LINE.search(_log_file_text(run.log_dir))
@@ -314,10 +342,10 @@ def test_console_log_can_be_turned_off(tmp_path):
     assert LOG_LINE.search(console) is None, console[:500]
     assert PROBE not in console, console[:500]
     assert run.stdio.count(PROBE) == 2 * run.result["probes"], run.stdio[:500]
+    assert UNSAFE_WARNING not in console, console[:500]
+    assert UNSAFE_WARNING not in run.stdio, run.stdio[:500]
     if JVM:
-        assert UNSAFE_WARNING not in console, console[:500]
         assert run.result["unsafe"], UNSAFE_TRIGGER_FAILED
-        assert UNSAFE_WARNING in run.stdio, run.stdio[:500]
     assert LOG_LINE.search(_log_file_text(run.log_dir))