JVM build: Java System.out/System.err go to a file the library owns when the console is off (Windows data corruption)

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

@@ -43,6 +43,8 @@ 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.
+
 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.
 
 == Choose the directory

src/arcadedb/_logdir.py

@@ -11,6 +11,13 @@
 the runtime caches the OS handle of stdout and stderr at start-up. A host that redirects fd 1 or 2 afterwards (pytest's fd capture,
 a service, an embedding application) closes that handle, a database file opened later can get the same handle value, and the next
 console log line is written into that file. The log file does not have that problem: the engine opens it itself.
+
+Console logging is not the only Java code that writes to the cached handle: a library that prints or ``e.printStackTrace()`` goes
+through ``System.out`` and ``System.err``, and the runtime's own warnings (the JEP 498 warning for ``sun.misc.Unsafe``, which jvector
+causes on the first reopen of a vector index) go through ``System.initialErr``, a copy of ``System.err`` that ``System.setErr`` does not
+change. So with the console off, the JVM build points all three streams at ``arcadedb-stdio.log`` in the log directory, a file the
+library opens itself, right after the JVM starts (``jvm.py``, :func:`stdio_log_path`). The runtime's start-up text (``WARNING: Using incubator modules: jdk.incubator.vector``) is printed while the
+JVM is created, before any of this can run, and still goes to the real stderr of the process.
 """
 
 import os
@@ -30,6 +37,9 @@
 # The config without the console handler has its own file name, so that two processes with different console settings that share a
 # log directory never replace each other's file between the write and the engine's first log call.
 FILE_ONLY_CONFIG_NAME = "logging-file-only.properties"
+# Where Java's System.out and System.err go while the console is off. A file of its own, not arcadedb.log: the engine's file handler
+# owns that one (it rotates it, and on Windows a rename of a file another handle holds open fails).
+STDIO_LOG_NAME = "arcadedb-stdio.log"
 CONSOLE_HANDLER = "java.util.logging.ConsoleHandler"
 
 # The engine's arcadedb-log.properties without its file pattern, for the native build: the image holds the engine's copy as a
@@ -106,6 +116,11 @@ def console_enabled() -> bool:
     return sys.platform != "win32"
 
 
+def stdio_log_path(log_dir: Path) -> Path:
+    """The file that Java's ``System.out`` and ``System.err`` append to while the console is off (see the module docstring)."""
+    return Path(log_dir) / STDIO_LOG_NAME
+
+
 def logging_config_name(console: Optional[bool] = None) -> str:
     """The file name of the generated logging config: ``logging.properties`` with the console handler, ``logging-file-only.properties`` without."""
     if console is None:

src/arcadedb/jvm.py

@@ -22,9 +22,11 @@
 
 from . import aot as _aot
 from ._logdir import LOG_DIR_ENV as _LOG_DIR_ENV
+from ._logdir import console_enabled as _console_enabled
 from ._logdir import default_log_dir as _default_log_dir
 from ._logdir import logging_config_name as _logging_config_name
 from ._logdir import render_logging_config as _render_logging_config
+from ._logdir import stdio_log_path as _stdio_log_path
 from ._logdir import usable_log_dir as _usable_log_dir
 from ._logdir import write_logging_config as _write_logging_config
 from ._logging import get_logger
@@ -441,8 +443,15 @@ def start_jvm(
         only. Default: on, except on Windows, where a host that redirects fd 1
         or 2 after the JVM started (pytest capture, a service) leaves the JVM
         writing console lines to a handle that a database file can reuse.
+        With the console off, Java's ``System.out`` and ``System.err`` (a library
+        that prints) and the runtime's own warnings (``System.initialErr``) also
+        append to ``arcadedb-stdio.log`` in the log directory, for the same reason; the
+        runtime's start-up warning, printed while the JVM is created, still goes
+        to the process's stderr. With ``1`` on Windows, that risk stays: do not
+        redirect fd 1 or 2 after the first database is opened.
         Needs to be set before the first JVM start. A
-        ``-Djava.util.logging.config.file=`` in ``jvm_args`` replaces it.
+        ``-Djava.util.logging.config.file=`` in ``jvm_args`` replaces the
+        logging config, not the stream redirect.
 
     ARCADEDB_JVM_ERROR_FILE (optional)
         Path for JVM crash logs (default: ``hs_err_pid%p.log`` in the log
@@ -545,6 +554,8 @@ def start_jvm(
     except Exception as e:
         raise ArcadeDBError(f"Failed to start JVM: {e}") from e
 
+    _redirect_java_stdio(log_dir)
+
     if not _JVM_INTERRUPT:
         _restore_python_signal_handlers()
 
@@ -569,6 +580,59 @@ def start_jvm(
         faulthandler.disable()
 
 
+def _redirect_java_stdio(log_dir: Path) -> None:
+    """With the console off, point ``System.out`` and ``System.err`` at a file the library owns.
+
+    On Windows the runtime caches the OS handle of stdout and stderr when it starts. A host that later redirects fd 1 or 2 (pytest's
+    fd capture, a service, an embedding application) closes that handle, a database page file opened afterwards can get the same
+    handle value, and the next ``System.out`` or ``System.err`` write lands in the page file (the JVM twin of the native bug that
+    ``ARCADEDB_LOG_CONSOLE`` fixed for the engine's own console log). Removing the console log handler does not cover every writer:
+    a library that prints, ``printStackTrace()``, and the runtime's own warnings. ``System.setOut`` and ``System.setErr`` reach the
+    first two; the runtime prints its own warnings (the JEP 498 warning for ``sun.misc.Unsafe``, which jvector triggers when it
+    unmaps a graph file on the first reopen of a vector index; the JEP 472 warning for restricted methods) to ``System.initialErr``,
+    a copy of the stream over the cached stderr handle that it keeps for exactly that purpose, so that is replaced too. A
+    ``PrintStream`` on a file opened here has no cached handle, whatever the host does with fd 1 and 2.
+
+    Only with the console off, which is the default on Windows only: on Linux and macOS the runtime writes to fd 1 and 2 by number
+    and follows a redirect, so the default there is unchanged. ``ARCADEDB_LOG_CONSOLE=1`` on Windows keeps the runtime's own
+    streams (the risk stays; see the option's text in :func:`start_jvm`). The text the runtime prints while the JVM is created comes
+    before this runs and still goes to the process's stderr.
+    """
+    if _console_enabled():
+        return
+    path = _stdio_log_path(log_dir)
+    try:
+        system = jpype.JClass("java.lang.System")
+        stream = jpype.JClass("java.io.PrintStream")(
+            jpype.JClass("java.io.FileOutputStream")(str(path), True), True, "UTF-8"
+        )
+        system.setOut(stream)
+        system.setErr(stream)
+    except (
+        Exception
+    ) as exc:  # the console stays as it was; never stop the start for a log file
+        _LOGGER.warning(
+            "Cannot send the Java stdout and stderr to %s (%s); they keep the process's own streams",
+            path,
+            exc,
+        )
+        return
+    try:
+        # setErr does not reach the runtime's own warnings: they are printed to System.initialErr, the stream that the runtime made
+        # over the cached stderr handle before any application code ran (the JEP 498 warning for sun.misc.Unsafe, which jvector
+        # prints on the first reopen of a vector index; the JEP 472 warning for restricted methods). It is a plain static field of
+        # java.lang.System, which --add-opens=java.base/java.lang (a default of this package) makes writable.
+        field = system.class_.getDeclaredField("initialErr")
+        field.setAccessible(True)
+        field.set(None, stream)
+    except Exception as exc:  # the runtime's own warnings keep the cached handle
+        _LOGGER.warning(
+            "Cannot send the Java runtime's own warnings to %s (%s); they keep the process's own stderr",
+            path,
+            exc,
+        )
+
+
 def _aot_flags(aot: Optional[bool], jvm_args: list, classpath: str) -> list:
     """AOT cache flags for this start; empty when off, unsupported or on any error."""
     if not _aot.enabled(aot):