diff --git a/docs/modules/ROOT/pages/how-to/logs.adoc b/docs/modules/ROOT/pages/how-to/logs.adoc index 2e57781..6106ebb 100644 --- a/docs/modules/ROOT/pages/how-to/logs.adoc +++ b/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 diff --git a/src/arcadedb/_logdir.py b/src/arcadedb/_logdir.py index b5ee8d7..b945f8c 100644 --- a/src/arcadedb/_logdir.py +++ b/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: diff --git a/src/arcadedb/jvm.py b/src/arcadedb/jvm.py index 7e26124..81fcbbc 100644 --- a/src/arcadedb/jvm.py +++ b/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): diff --git a/tests/test_log_redirect.py b/tests/test_log_redirect.py index a126f1e..ee38b97 100644 --- a/tests/test_log_redirect.py +++ b/tests/test_log_redirect.py @@ -1,15 +1,34 @@ -"""A host that redirects fd 1 and 2 after the library started must not get engine log text written into database files. +"""A host that redirects fd 1 and 2 after the library started must not get engine log text, or Java's own output, written into database files. On Windows the runtime caches the OS handle of stdout and stderr at start-up. pytest's fd capture, a service or an embedding application that dup2s onto fd 1 or 2 afterwards closes that handle; a database file opened later can get the same handle value, -and the next console log line was then written into that file (a bucket file that started with +and the next write through the cached handle was then written into that file (a bucket file that started with ``2026-10-25 19:37:03.759 INFO [LSMVectorIndex] Discovered and loaded graph file ...``, vector index files with ``Graph build validating ...``; in the tests that showed as ``Invalid vector id -N``, ``Invalid position N (size=65536)`` or no result after a -reopen). The fix is that the engine logs to its file only on Windows unless ``ARCADEDB_LOG_CONSOLE`` asks for the console. - -The redirect test runs on every platform: on POSIX writes go to fd 1 and 2 by number, so it passes trivially there, and on Windows -it is the real check. It does the same work as ``test_lsm_persistence`` and ``test_lsm_vector_search_approximate_persistence`` in -``test_vector.py``: create a vector index, build the graph, close, reopen, query. +reopen). Two fixes close it, in two layers: + +* The engine logs to its file only on Windows unless ``ARCADEDB_LOG_CONSOLE`` asks for the console (no JUL console handler). +* With the console off, the JVM build also replaces Java's ``System.out``, ``System.err`` and ``System.initialErr`` with a stream on + ``arcadedb-stdio.log`` in the log directory (``jvm._redirect_java_stdio``). Text that the first fix left on the cached handle + reached a page file with ``Invalid position 793803132 (size=65536)`` in the JVM test run 40250615309 on Windows, one run in + four. The text was the runtime's warning ``A terminally deprecated method in sun.misc.Unsafe has been called`` (JEP 498), which + jvector causes when it unmaps a graph file on the first reopen of a vector index. The runtime prints it to ``System.initialErr``, + the copy of ``System.err`` that it makes before application code runs and that ``System.setErr`` does not change, so replacing + ``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 redirect tests run on every platform: 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 console-off test also fails on POSIX without the second fix, because +the Java probes below then go to the redirect target. The child does the same work as ``test_lsm_persistence`` and +``test_lsm_vector_search_approximate_persistence`` in ``test_vector.py`` (create a vector index, build the graph, close, reopen, +query), ``ARCADEDB_REDIRECT_REPEATS`` times in one process (default 10), and after every step prints a probe line through Java's +``System.out`` and ``System.err``: a write through the cached handle that hits a file whenever a database file owns the handle +value, which no log line has to be around for. Every file under the data directory is then scanned for log text and probes. + +One text is not covered: the runtime prints ``WARNING: Using incubator modules: jdk.incubator.vector`` to stderr while the JVM is +created, before the library can install its streams. In the child the JVM starts before the redirect, so that line goes to the +parent's pipe (``proc.stderr``), never to the redirect target. Run 40250615309 showed it in the failure message only because the +old assertion message joined stdout, stderr and the redirect target into one text; the messages below name each part. """ import json @@ -18,6 +37,7 @@ import subprocess # nosec B404 - test-controlled child process import sys from pathlib import Path +from types import SimpleNamespace import pytest @@ -28,6 +48,25 @@ rb"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} " rb"(?:SEVERE|WARNING|INFO|CONFIG|FINE|FINER|FINEST)\b" ) +# What the child prints through Java's System.out and System.err after every step. +PROBE = b"ARCADEDB-STDIO-PROBE" +# The runtime's warning for the first use of a sun.misc.Unsafe memory method (JEP 498). jvector prints it when it unmaps a graph +# file, on the first reopen of a vector index. The runtime writes it to System.initialErr, not to System.err. +UNSAFE_WARNING = b"A terminally deprecated method in sun.misc.Unsafe has been called" +UNSAFE_TRIGGER_FAILED = ( + "the child could not unmap a file with jvector's SimpleMappedReader.Supplier, the call that makes the runtime print " + "UNSAFE_WARNING; if jvector no longer uses sun.misc.Unsafe, pick another call that does" +) +# Text of the runtime's own that never belongs in a database file. +STRAY_TEXT = re.compile( + LOG_LINE.pattern + + rb"|" + + PROBE + + rb"|WARNING: Using incubator modules|" + + re.escape(UNSAFE_WARNING) +) + +REPEATS = int(os.environ.get("ARCADEDB_REDIRECT_REPEATS", "10")) CHILD = """ import json @@ -35,9 +74,11 @@ import sys import time +import jpype + import arcadedb -mode, data_dir, sink, result = sys.argv[1:5] +mode, data_dir, sink, result, repeats, marker = sys.argv[1:7] # start the library first: on Windows it caches the handles of fd 1 and 2 now warm = arcadedb.create_database(os.path.join(data_dir, "warm")) @@ -51,45 +92,94 @@ os.dup2(fd, 2) os.close(fd) -db_path = os.path.join(data_dir, "db") +system = jpype.JClass("java.lang.System") +probes = 0 + +# the runtime's own warning, now and not at some later reopen: jvector unmaps a file with sun.misc.Unsafe.invokeCleaner +unsafe = False +try: + target = os.path.join(os.path.dirname(sink), "mapped.bin") + with open(target, "wb") as handle: + handle.write(b"x" * 64) + supplier = jpype.JClass("io.github.jbellis.jvector.disk.SimpleMappedReader$Supplier") + supplier(jpype.JClass("java.nio.file.Path").of(target, [])).close() + unsafe = True +except Exception: + pass # jvector changed: the reopen below still reaches the warning if the runtime prints it + + +def probe(step): + # a Java-level write to stdout and to stderr, as a runtime warning or a library that prints does + global probes + probes += 1 + system.out.println(f"{marker} out {probes} {step}") + system.err.println(f"{marker} err {probes} {step}") + + vectors = [[1.0, 0.0, 0.0], [0.9, 0.1, 0.0], [0.8, 0.2, 0.0]] for i in range(256): vectors.append([0.01, ((i % 16) + 1) / 10.0, (((i // 16) % 16) + 1) / 10.0]) -with arcadedb.create_database(db_path) as db: - db.command("sql", "CREATE VERTEX TYPE Doc") - db.command("sql", "CREATE PROPERTY Doc.embedding ARRAY_OF_FLOATS") - index = db.create_vector_index( - "Doc", "embedding", dimensions=3, quantization="PRODUCT" - ) - with db.transaction(): - for vec in vectors: - db.command( +counts = set() +neighbor_counts = set() +for run in range(int(repeats)): + db_path = os.path.join(data_dir, f"db{run}") + probe("before create") + with arcadedb.create_database(db_path) as db: + db.command("sql", "CREATE VERTEX TYPE Doc") + db.command("sql", "CREATE PROPERTY Doc.embedding ARRAY_OF_FLOATS") + probe("schema") + index = db.create_vector_index( + "Doc", "embedding", dimensions=3, quantization="PRODUCT" + ) + probe("index") + with db.transaction(): + for vec in vectors: + db.command( + "sql", + "INSERT INTO Doc SET embedding = ?", + arcadedb.to_java_float_array(vec), + ) + probe("insert") + index.build_graph_now() + probe("graph") + + with arcadedb.open_database(db_path) as db: + probe("reopen") + counts.add( + db.query("sql", "SELECT count(*) as count FROM Doc").first().get("count") + ) + neighbors = [] + for _ in range(100): # the graph loads asynchronously after the reopen + rows = db.query( "sql", - "INSERT INTO Doc SET embedding = ?", - arcadedb.to_java_float_array(vec), - ) - index.build_graph_now() - -with arcadedb.open_database(db_path) as db: - count = db.query("sql", "SELECT count(*) as count FROM Doc").first().get("count") - neighbors = [] - for _ in range(100): # the graph loads asynchronously after the reopen - rows = db.query( - "sql", "SELECT vectorNeighbors('Doc[embedding]', [1.0, 0.0, 0.0], 1) as res" - ).to_list() - neighbors = rows[0].get("res") - if neighbors: - break - time.sleep(0.1) + "SELECT vectorNeighbors('Doc[embedding]', [1.0, 0.0, 0.0], 1) as res", + ).to_list() + neighbors = rows[0].get("res") + probe("query") + if neighbors: + break + time.sleep(0.1) + neighbor_counts.add(len(neighbors)) with open(result, "w") as out: - json.dump({"count": count, "neighbors": len(neighbors)}, out) + json.dump( + { + "counts": sorted(counts), + "neighbors": sorted(neighbor_counts), + "runs": int(repeats), + "probes": probes, + "unsafe": unsafe, + }, + out, + ) """ -def _run(tmp_path, mode, console=None): - """Run CHILD in a fresh process; return (result dict, completed process, data dir, log dir, sink file).""" +def _run(tmp_path, mode, console=None, repeats=REPEATS): + """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. + """ data_dir = tmp_path / "data" data_dir.mkdir() log_dir = tmp_path / "log" @@ -104,25 +194,52 @@ def _run(tmp_path, mode, console=None): if console is not None: env["ARCADEDB_LOG_CONSOLE"] = console proc = subprocess.run( # nosec B603 - fixed argument list, no shell - [sys.executable, "-c", CHILD, mode, str(data_dir), str(sink), str(result)], + [ + sys.executable, + "-c", + CHILD, + mode, + str(data_dir), + str(sink), + str(result), + str(repeats), + PROBE.decode(), + ], env=env, capture_output=True, - timeout=600, + timeout=1800, ) sink_text = sink.read_bytes() if sink.exists() else b"" + # Each part is named: the runtime's start-up warning is in stderr (the pipe), never in the redirect target. assert proc.returncode == 0, ( - proc.stdout.decode(errors="replace") - + proc.stderr.decode(errors="replace") - + sink_text.decode(errors="replace") + f"child exit {proc.returncode}\n" + f"--- stdout:\n{proc.stdout.decode(errors='replace')}\n" + f"--- stderr:\n{proc.stderr.decode(errors='replace')}\n" + f"--- redirect target:\n{sink_text.decode(errors='replace')}" + ) + stdio = log_dir / _logdir.STDIO_LOG_NAME + return SimpleNamespace( + result=json.loads(result.read_text()), + proc=proc, + data_dir=data_dir, + log_dir=log_dir, + sink=sink_text, + stdio=stdio.read_bytes() if stdio.exists() else b"", + expected={ + "counts": [259], + "neighbors": [1], + "runs": repeats, + "probes": json.loads(result.read_text())["probes"], + "unsafe": json.loads(result.read_text())["unsafe"], + }, ) - return json.loads(result.read_text()), proc, data_dir, log_dir, sink_text -def _log_lines_in_files(root: Path): - """Every file under ``root`` that holds an engine log line, with the first match.""" +def _stray_text_in_files(root: Path): + """Every file under ``root`` that holds engine log text, a probe or the runtime's warning, with the first match.""" found = [] for path in sorted(p for p in root.rglob("*") if p.is_file()): - match = LOG_LINE.search(path.read_bytes()) + match = STRAY_TEXT.search(path.read_bytes()) if match: found.append((str(path.relative_to(root)), match.group(0))) return found @@ -133,39 +250,65 @@ def _log_file_text(log_dir: Path) -> bytes: def test_redirecting_fd_1_and_2_leaves_the_database_files_clean(tmp_path): - result, _, data_dir, log_dir, _ = _run(tmp_path, "redirect") - assert result == {"count": 259, "neighbors": 1} - assert _log_lines_in_files(data_dir) == [] + run = _run(tmp_path, "redirect") + assert run.result == run.expected + assert ( + run.result["probes"] >= 6 * REPEATS + ) # the probes ran: a clean scan is not clean because nothing wrote + assert _stray_text_in_files(run.data_dir) == [] # the work did log, to the file: the scan above is not clean because nothing was logged - assert LOG_LINE.search(_log_file_text(log_dir)), list(log_dir.iterdir()) + assert LOG_LINE.search(_log_file_text(run.log_dir)), list(run.log_dir.iterdir()) def test_redirect_with_the_console_off_sends_nothing_to_the_redirect_target(tmp_path): - # ARCADEDB_LOG_CONSOLE=0 is the Windows default on every platform: nothing reaches fd 1 or 2 even where that is safe - result, _, data_dir, log_dir, sink = _run(tmp_path, "redirect", console="0") - assert result == {"count": 259, "neighbors": 1} - assert LOG_LINE.search(sink) is None, sink[:500] - assert _log_lines_in_files(data_dir) == [] - assert LOG_LINE.search(_log_file_text(log_dir)) + # ARCADEDB_LOG_CONSOLE=0 is the Windows default on every platform: nothing reaches fd 1 or 2 even where that is safe, and + # Java's System.out and System.err append to arcadedb-stdio.log + run = _run(tmp_path, "redirect", console="0") + assert run.result == run.expected + assert LOG_LINE.search(run.sink) is None, run.sink[:500] + assert PROBE not in run.sink, run.sink[:500] + assert UNSAFE_WARNING not in run.sink, run.sink[:500] + assert _stray_text_in_files(run.data_dir) == [] + assert LOG_LINE.search(_log_file_text(run.log_dir)) + # every probe, from both streams, is in the file the library owns (and nowhere else) + 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 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] def test_console_log_can_be_turned_on(tmp_path): # no redirect here: on Windows the console is off by default because of the redirect hazard above, and a child whose fd 1 and 2 # are the parent's pipes is the safe way to see that the opt-in works - result, proc, data_dir, log_dir, _ = _run(tmp_path, "plain", console="1") - assert result == {"count": 259, "neighbors": 1} - console = proc.stdout + proc.stderr + run = _run(tmp_path, "plain", console="1", repeats=1) + assert run.result == run.expected + console = run.proc.stdout + run.proc.stderr assert LOG_LINE.search(console), console[:500] - assert _log_lines_in_files(data_dir) == [] - assert LOG_LINE.search(_log_file_text(log_dir)) + # 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 run.stdio == b"" + assert _stray_text_in_files(run.data_dir) == [] + assert LOG_LINE.search(_log_file_text(run.log_dir)) def test_console_log_can_be_turned_off(tmp_path): - result, proc, _, log_dir, _ = _run(tmp_path, "plain", console="0") - assert result == {"count": 259, "neighbors": 1} - console = proc.stdout + proc.stderr + run = _run(tmp_path, "plain", console="0", repeats=1) + assert run.result == run.expected + console = run.proc.stdout + run.proc.stderr assert LOG_LINE.search(console) is None, console[:500] - assert LOG_LINE.search(_log_file_text(log_dir)) + assert PROBE not in console, console[:500] + assert UNSAFE_WARNING not in console, console[:500] + assert run.stdio.count(PROBE) == 2 * run.result["probes"], run.stdio[: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)) + + +def test_the_stdio_log_is_in_the_log_dir(tmp_path): + assert _logdir.stdio_log_path(tmp_path) == tmp_path / "arcadedb-stdio.log" + # not a file the engine's file handler owns (arcadedb.log.N), so a rotation never renames it away + assert not _logdir.STDIO_LOG_NAME.startswith("arcadedb.log") @pytest.mark.parametrize(