From 168b5a0c532b6b373e2ccc4e33f1fdfda20caa47 Mon Sep 17 00:00:00 2001 From: Taewoon Kim Date: Mon, 26 Oct 2026 18:41:10 +0900 Subject: [PATCH] Native and JVM builds: switch off the JEP 498 sun.misc.Unsafe warning at its source The native image prints jvector's sun.misc.Unsafe warning (the first reopen of a vector index) to the stderr handle it 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). The image keeps sun.misc.Unsafe's option as a build-time constant, so JavaArgs in the glue jar's native-image.properties sets -Dsun.misc.unsafe.memory.access=allow for the builder. The JVM build gets --sun-misc-unsafe-memory-access=allow as a default (a caller's value wins), next to the System.initialErr redirect of #88. test_log_redirect.py now checks the warning is on no stream and in no file on both builds, and keeps the initialErr redirect covered with the option set back to warn. Co-Authored-By: Claude Sonnet 5.5 --- docs/modules/ROOT/pages/how-to/logs.adoc | 2 +- native/scripts/build-image.sh | 3 ++ .../native-image.properties | 8 ++++ src/arcadedb/jvm.py | 9 ++++ tests/test_jvm_args.py | 16 +++++++ tests/test_log_redirect.py | 42 +++++++++++++++---- 6 files changed, 72 insertions(+), 8 deletions(-) diff --git a/docs/modules/ROOT/pages/how-to/logs.adoc b/docs/modules/ROOT/pages/how-to/logs.adoc index 6106ebb8..f11b0f72 100644 --- a/docs/modules/ROOT/pages/how-to/logs.adoc +++ b/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. diff --git a/native/scripts/build-image.sh b/native/scripts/build-image.sh index e454c075..72ac2aa8 100755 --- a/native/scripts/build-image.sh +++ b/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" || { diff --git a/native/src/main/resources/META-INF/native-image/org.humemai/arcadedb-native-lib/native-image.properties b/native/src/main/resources/META-INF/native-image/org.humemai/arcadedb-native-lib/native-image.properties index 22341674..7adf7fb8 100644 --- a/native/src/main/resources/META-INF/native-image/org.humemai/arcadedb-native-lib/native-image.properties +++ b/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 diff --git a/src/arcadedb/jvm.py b/src/arcadedb/jvm.py index 81fcbbc1..2289ccf6 100644 --- a/src/arcadedb/jvm.py +++ b/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") diff --git a/tests/test_jvm_args.py b/tests/test_jvm_args.py index de085dda..d43b397f 100644 --- a/tests/test_jvm_args.py +++ b/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. diff --git a/tests/test_log_redirect.py b/tests/test_log_redirect.py index cbf73939..d87f6636 100644 --- a/tests/test_log_redirect.py +++ b/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))