Skip to content

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

Open
tae898 wants to merge 1 commit into
mainfrom
jvm-windows-java-stdio
Open

tae898 wants to merge 1 commit into
mainfrom
jvm-windows-java-stdio

Conversation

@tae898

@tae898 tae898 commented Oct 26, 2026 •

Copy link
Copy Markdown
Collaborator

What

The JVM twin of #78. #78 removed the JUL console handler on Windows, but Java-level writes to System.out and System.err 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 both streams, 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.

Evidence

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.
  • 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.

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); with it all 21 tests pass.

Checks run

black, isort --profile black, Bandit 1.9.4 (-c pyproject.toml -r src tests --severity-level low --confidence-level low, clean), scripts/check_no_embedded_name.py, and tests/test_log_redirect.py on Linux (Python 3.14, engine 26.10.2 jars). The Windows proof (bar: 0 failures, no log text in any database file):

  • test-jvm.yml dispatched twice on this branch: runs 40252284414 and 40252287194 (the pull_request run is 40252214662).
  • A temporary loop workflow on a separate branch, no PR, deleted after the run (run 40252312732): Windows Python 3.13, 50 runs of tests/test_log_redirect.py per leg with pytest's default capture, with and without the fix (jvm.py from main), at 1 and at 10 repeats per child. The numbers are in the first comment.

🤖 Generated with Claude Code

…owns when the console is off

On Windows the runtime caches the OS handle of stdout and stderr at start-up. A host that redirects fd 1 or 2 later closes it, 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 (run 40250615309: Invalid position 793803132 (size=65536)). The JVM twin of #78, which removed the JUL console handler but not the other Java writers.

start_jvm() now points both streams at arcadedb-stdio.log in the log directory right after startJVM, when the console is off (Windows default, or ARCADEDB_LOG_CONSOLE=0). The test repeats redirect, index, reopen and query ten times in one child, prints a Java probe after every step and scans every database file.

Co-Authored-By: Claude Sonnet 5.5 <[email protected]>

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant