[tae898]

What

The JVM twin of #78. #78 removed the JUL console handler on Windows, but Java-level writes to System.out and System.err, and the runtime's own warnings, still use the OS handle that the runtime cached at start-up. With the console off (the default on Windows, or ARCADEDB_LOG_CONSOLE=0), start_jvm() now replaces System.out, System.err and System.initialErr, right after startJVM, with one PrintStream on arcadedb-stdio.log in the log directory (_logdir.stdio_log_path()). The file is opened by the library, so no cached handle is involved, whatever the host does with fd 1 and 2.

System.initialErr is the part that the first version of this PR missed. It is the copy of System.err that the runtime makes before any application code runs, and System.setErr does not change it. The runtime prints its own warnings to it, and one of them is printed in every run of the vector tests (see Root cause).

Root cause

The first version of this PR (head 2e33a26) still failed on Windows in about one run in 20 to 60 (the temporary loop of run 40252312732: 3 failures in 50 runs at 1 repeat, 1 in 50 at 10 repeats; the ARCADEDB-STDIO-PROBE lines in the redirect target in that loop's log came from the control legs that run main's jvm.py, not from the fixed legs). Every failure of the fixed legs was the same Invalid position 793803132 (size=65536): the same number each time, so the same text each time.

A temporary Windows diagnostic (no PR, deleted; run 40264486763 builds the wheel, run 40265118569 loops) found the writer in two ways:

• In the 3 failing runs of 240 with the redirect (Invalid position 793803132), the scan of the database directory found db0\Doc_0.1.65536.v0.bucket starting with the four lines below, at offsets 0, 75 and 297. With no redirect (plain, 120 runs) nothing failed.
• A canary file on the stale handle: after the child's dup2 it opens a file until CreateFile returns the value that FileDescriptor.err cached, and keeps it. In 114 of 120 and 117 of 120 runs that canary held exactly these four lines (in the other 9 runs the canary could not take the value).

WARNING: A terminally deprecated method in sun.misc.Unsafe has been called
WARNING: sun.misc.Unsafe::invokeCleaner has been called by io.github.jbellis.jvector.disk.SimpleMappedReader$Supplier (file:/C:/hostedtoolcache/windows/Python/3.13.16/x64/Lib/site-packages/arcadedb/jars/jvector-4.0.2.jar)
WARNING: Please consider reporting this to the maintainers of class io.github.jbellis.jvector.disk.SimpleMappedReader$Supplier
WARNING: sun.misc.Unsafe::invokeCleaner will be removed in a future release

That is the JEP 498 warning (JDK 24 and later): jvector unmaps a graph file with Unsafe.invokeCleaner when the vector index is reopened, and the runtime prints the warning once. sun.misc.Unsafe.log prints it to jdk.internal.misc.VM.initialErr(), which returns System.initialErr, not to System.err (the JEP 472 warning for restricted methods in java.lang.Module does the same). System.setErr leaves it on the cached handle. When the host's dup2 onto fd 2 has closed that handle and a page file opened later gets the same value, the four lines land in the page file.
Nothing else in java.base holds the cached handle: a scan of the module finds FileDescriptor.out and FileDescriptor.err only in System (which makes the three streams) and in JdkConsoleImpl.

Evidence of the first version

Dispatch run 40250615309 (test-jvm.yml on the PR #87 branch windows-default-capture), job 121341603694, Windows Python 3.13: tests/test_log_redirect.py::test_redirect_with_the_console_off_sends_nothing_to_the_redirect_target failed with ArcadeDBError: Reading the result set failed: java.lang.IllegalArgumentException: Invalid position 793803132 (size=65536), which is text read as a page position, the #78 signature. The other Windows legs of that run, and 3 of the 4 legs of the other run, passed: it is intermittent.

The WARNING: Using incubator modules: jdk.incubator.vector in that failure message is not a leak into the redirect target. The child starts the JVM before it redirects, so the runtime prints that line to the parent's pipe (proc.stderr=b'WARNING: Using incubator modules: jdk.incubator.vector\r\n' in the log), and the old assertion message joined stdout, stderr and the redirect target into one text. The test needs no weaker expectation: the new message names each part. A host that redirects fd 2 before it starts the JVM does get that one line in its own target, which is its choice. Nothing the library prints after startJVM can reach it.

Design

• Windows by default, and wherever ARCADEDB_LOG_CONSOLE=0 asks for the console off, on any platform. The default on Linux and macOS is unchanged: the runtime writes to fd 1 and 2 by number there and follows a redirect. Tying it to the console setting (not to sys.platform) keeps one rule, and lets the Linux CI exercise the code.
• arcadedb-stdio.log, not arcadedb.log: the engine's file handler owns and rotates that one, and on Windows renaming a file that another handle holds open fails. Several processes that share a log directory append to the same file; a write is small.
• ARCADEDB_LOG_CONSOLE=1 on Windows keeps the runtime's own streams, so the risk stays; it is documented (jvm.start_jvm, _logdir, docs/.../how-to/logs.adoc). Reopening CONOUT$ is not done: it would ignore a redirect that the host set up on purpose before the start.
• System.initialErr is replaced by reflection (System.class.getDeclaredField("initialErr"), a plain static field). --add-opens=java.base/java.lang=ALL-UNNAMED is a default of this package already (_build_jvm_args). If it cannot be set (a caller's own --add-opens for another package set, a future JDK that renames the field), start_jvm() logs a warning and the runtime's own warnings keep the cached handle.
• A failure to open the file only logs a warning; the start goes on.

Tests

tests/test_log_redirect.py is stronger on every build:

• The child repeats redirect, create index, build graph, close, reopen and query ARCADEDB_REDIRECT_REPEATS times in one process (default 10), and after every step prints a probe through Java's System.out and System.err. A probe is a write through the cached handle that lands in a page file whenever a database file owns the handle value, with no log line needed.

• Every file under the data directory is scanned for engine log lines, probes and the runtime warning.

• With the console off, the redirect target must hold no log line and no probe, and arcadedb-stdio.log must hold every probe, from both streams (exact count).

• With the console on, the probes are on the console and there is no stdio file.

• The child also unmaps a file with jvector's SimpleMappedReader.Supplier right after the redirect, so the runtime prints the JEP 498 warning at once (it also prints it at the first reopen). The warning must not be in the redirect target, the console or any database file, and must be in arcadedb-stdio.log.

Without the fix the console-off redirect test and test_console_log_can_be_turned_off fail on Linux too (the probes go to fd 1 and 2); without the System.initialErr part they fail on Linux on the warning alone (checked against 2e33a26); with it all 21 tests pass.

Checks run

black, isort --profile black, tests/test_log_dir.py, tests/test_log_redirect.py and tests/test_jvm_args.py on Linux (Python 3.12, JRE 25.0.5, engine and jars of a 26.11.1.dev0 JVM wheel). The Windows proof (bar: 0 failures, no text in any database file):

• Temporary loop workflow on a separate branch, no PR, deleted after the run (run 40266357163; it reuses the wheel of run 40264486763 and overlays this branch's src/arcadedb/*.py): Windows Python 3.13, test_redirecting_fd_1_and_2_leaves_the_database_files_clean, test_redirect_with_the_console_off_sends_nothing_to_the_redirect_target and test_console_log_can_be_turned_off per iteration, pytest's default capture. 100 iterations at 1 repeat per child, twice (200), and 50 at 10 repeats per child, twice (100): 0 failures in 300 iterations (the version without the System.initialErr part failed about 1 in 20 to 60). The canary legs (60 iterations with the stale handle taken over by a canary file, 60 without) show the canary empty and the redirect target empty in all 120.
• test-jvm.yml dispatched twice on this branch at 9a35d13: runs 40267979586 and 40267982374.

🤖 Generated with Claude Code

[tae898]

Back to draft: CI is green, but a Windows loop that runs tests/test_log_redirect.py repeatedly still fails most runs on this head (2e33a26): with the console off the probe text still reaches the redirect target, and the database-files test reads Invalid position 793803132 (size=65536), i.e. log text in a database file. The cause is being traced; this PR is ready again only after at least 20 Windows loop runs with 0 failures.

[tae898]

Correction to my earlier comment: the probe text in the redirect target came from the control legs (main's jvm.py), not from this branch. This branch's real failure was rarer (about 1 run in 20 to 60): Invalid position 793803132 (size=65536), i.e. text inside a database page. Root cause, now fixed in 9a35d13: jvector's SimpleMappedReader$Supplier calls sun.misc.Unsafe.invokeCleaner when a vector index is reopened; JDK 25 prints its JEP 498 warning through jdk.internal.misc.VM.initialErr(), a copy of System.err made before application code runs and not changed by System.setErr; after the host's dup2 onto fd 2 that stale HANDLE value is reused by a page file. The fix also points System.initialErr at the library's stdio log. Windows loop with the fix: 300 real-test iterations and 120 diagnostic runs, 0 failures (run 40266357163); full test-jvm matrix green (run 40267979586). Details in the PR description.