diff --git a/.github/workflows/test-jvm.yml b/.github/workflows/test-jvm.yml index cf3f911..54344c6 100644 --- a/.github/workflows/test-jvm.yml +++ b/.github/workflows/test-jvm.yml @@ -399,6 +399,10 @@ jobs: # progress log. sys capture never touches the fds, so the JVM keeps writing to # the runner's own pipes (its log lines appear in this job's log). No test uses # capfd. + # The package no longer logs to the console on Windows by default + # (ARCADEDB_LOG_CONSOLE, src/arcadedb/_logdir.py), which removes the cause, and + # tests/test_log_redirect.py redirects fd 1 and 2 on purpose. This flag stays + # until a run with the default capture has passed on the Windows legs. CAPTURE="" if [ "$RUNNER_OS" = "Windows" ]; then CAPTURE="--capture=sys"; fi set +e # Don't exit on test failures diff --git a/docs/modules/ROOT/pages/how-to/logs.adoc b/docs/modules/ROOT/pages/how-to/logs.adoc index 4019bbd..2e57781 100644 --- a/docs/modules/ROOT/pages/how-to/logs.adoc +++ b/docs/modules/ROOT/pages/how-to/logs.adoc @@ -1,5 +1,5 @@ = Where the logs go -:description: Where the engine writes its log file on the arcadedb and arcadedb-jvm packages, how to move it, and what the packages never write. +:description: Where the engine writes its log file on the arcadedb and arcadedb-jvm packages, how to move it, when it also logs to the console, and what the packages never write. Neither package writes a `log` directory into your working directory. The engine's own default is `./log/arcadedb.log`, relative to wherever the process started. Both packages replace it with a per-user directory, so a read-only working directory or a notebook that starts anywhere leaves no files behind. @@ -23,7 +23,27 @@ The log directory is `arcadedb/log` under your state directory: When the directory cannot be created or written, the package logs a warning and uses a new `arcadedb-log-*` directory under the system temp directory. -The directory holds the engine log (`arcadedb.log.0`, `arcadedb.log.1` and so on, up to 10 files of 100 MB), and the `logging.properties` that the package writes for the engine. The `arcadedb-jvm` package also keeps the JVM crash file `hs_err_pid.log` there. +The directory holds the engine log (`arcadedb.log.0`, `arcadedb.log.1` and so on, up to 10 files of 100 MB), and the logging configuration that the package writes for the engine (`logging.properties`, or `logging-file-only.properties` when the console is off, see below). The `arcadedb-jvm` package also keeps the JVM crash file `hs_err_pid.log` there. + +== Console output + +The engine logs to its file and, on Linux and macOS, to the console too (stderr). On Windows the console log is off by default: the log goes to the file only. + +The reason is a Windows detail. The runtime saves the OS handle of stdout and stderr when it starts. If your program redirects file descriptor 1 or 2 later (pytest's default output capture does this around every test, and so can a service or an application that embeds the library), Windows closes that handle and can give the same handle value to the next file that is opened, for example a database file. The next console log line is then written into that database file and corrupts it. The log file does not have this problem, because the engine opens it itself. + +Set `ARCADEDB_LOG_CONSOLE` before the first database is opened to choose on any platform: + +[source,bash] +---- +export ARCADEDB_LOG_CONSOLE=1 # also log to the console (Windows: only if your program never redirects fd 1 or 2) +export ARCADEDB_LOG_CONSOLE=0 # log to the file only (also on Linux and macOS) +---- + +`1`, `true`, `yes` and `on` turn the console log on, `0`, `false`, `no` and `off` turn it off. Any other value, and no value, gives the platform default above. The package writes the configuration without the console handler to `logging-file-only.properties` in the log directory, so processes with different settings that share a directory do not replace each other's file. + +A `java.util.logging.config.file` that you set yourself (see below) replaces all of this: its handlers decide where the log goes. + +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/native/src/main/java/io/github/jbellis/jvector/vector/cnative/LibraryLoader.java b/native/src/main/java/io/github/jbellis/jvector/vector/cnative/LibraryLoader.java index 7c6c731..bbc8f73 100644 --- a/native/src/main/java/io/github/jbellis/jvector/vector/cnative/LibraryLoader.java +++ b/native/src/main/java/io/github/jbellis/jvector/vector/cnative/LibraryLoader.java @@ -12,8 +12,16 @@ import java.io.File; import java.io.InputStream; import java.nio.file.Files; +import java.util.logging.Level; +import java.util.logging.Logger; public class LibraryLoader { + // java.util.logging, never System.err: on Windows the image caches the OS handle of stderr at start-up, and a host that redirects + // fd 2 afterwards closes it, so a database file opened later can get the same handle value and receive the text (see NativeExtras.swallowed). + private static void warn(final String message) { + Logger.getLogger(LibraryLoader.class.getName()).log(Level.WARNING, message); // looked up at the call, not in a static initializer + } + private LibraryLoader() { } @@ -47,7 +55,7 @@ public static boolean loadJvector() { System.load(f.getAbsolutePath()); return true; } catch (final UnsatisfiedLinkError | RuntimeException e) { - System.err.println("jvector: loading " + f + " failed: " + e); + warn("jvector: loading " + f + " failed: " + e); } } } @@ -64,7 +72,7 @@ public static boolean loadJvector() { Files.deleteIfExists(tmp.toPath()); } } catch (final Exception | UnsatisfiedLinkError e) { - System.err.println("jvector: loading the bundled " + name + " failed: " + e); + warn("jvector: loading the bundled " + name + " failed: " + e); } } return false; diff --git a/native/src/main/java/org/humemai/nativelib/NativeExtras.java b/native/src/main/java/org/humemai/nativelib/NativeExtras.java index 7fc3797..825dc1e 100644 --- a/native/src/main/java/org/humemai/nativelib/NativeExtras.java +++ b/native/src/main/java/org/humemai/nativelib/NativeExtras.java @@ -76,6 +76,8 @@ import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.atomic.AtomicLong; import java.util.concurrent.atomic.AtomicReference; +import java.util.logging.Level; +import java.util.logging.Logger; public final class NativeExtras { private NativeExtras() { @@ -131,9 +133,13 @@ public static CCharPointer alloc(final IsolateThread thread, final long size) { return UnmanagedMemory.malloc(WordFactory.unsigned(size)); } - /** A callback failure that must not stop an async writer: reported on stderr, not lost. */ + /** + * A callback failure that must not stop an async writer: logged, not lost. It goes through java.util.logging, never to System.err: + * on Windows the image caches the OS handle of stdout and stderr at start-up, and a host that redirects fd 1 or 2 afterwards (pytest + * capture, a service) closes that handle, so a database file opened later can get the same handle value and receive the text. + */ static void swallowed(final String where, final Throwable t) { - System.err.println("[arcadedb-native] " + where + " failed: " + t); + Logger.getLogger("org.humemai.nativelib").log(Level.WARNING, "[arcadedb-native] " + where + " failed: " + t); } /** Calls Python with an event whose reply nobody reads; a Python exception (reported in the reply) is logged, not lost. */ diff --git a/native/wheel/parity_wheel.py b/native/wheel/parity_wheel.py index ec03dad..8cc094f 100644 --- a/native/wheel/parity_wheel.py +++ b/native/wheel/parity_wheel.py @@ -100,6 +100,9 @@ a.python, "-m", "pytest", + # No --capture=sys on Windows: pytest's default fd capture (dup2 onto fd 1 and 2) is the regression check for engine log + # text landing in database files there (tests/test_log_redirect.py is the direct test; the whole-file runs of test_vector.py + # were the ones that failed before the engine stopped logging to the console on Windows). f"tests/{name}", "-q", "-p", diff --git a/src/arcadedb/_logdir.py b/src/arcadedb/_logdir.py index 777d7b0..b5ee8d7 100644 --- a/src/arcadedb/_logdir.py +++ b/src/arcadedb/_logdir.py @@ -6,6 +6,11 @@ system properties at it: ``arcadedb.server.logsDirectory`` (the directory) and ``java.util.logging.config.file`` (that file). The JVM build sets them as JVM arguments (``jvm.py``), the native build as isolate arguments (``_native/lib.py``). The engine reads both when it first logs, so they have to be in place before the first engine call. This module has no JVM and no JPype. + +The engine's console handler is off by default on Windows (``ARCADEDB_LOG_CONSOLE`` turns it on or off on any platform). On Windows +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. """ import os @@ -13,13 +18,19 @@ import sys import tempfile from pathlib import Path +from typing import Optional from ._logging import get_logger _LOGGER = get_logger(__name__) LOG_DIR_ENV = "ARCADEDB_LOG_DIR" +LOG_CONSOLE_ENV = "ARCADEDB_LOG_CONSOLE" LOGGING_CONFIG_NAME = "logging.properties" +# 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" +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 # resource, but an isolate argument has to name a real file, and there is no jar to read it from. tests/test_log_dir.py compares @@ -80,18 +91,54 @@ def default_log_dir() -> Path: return state_base_dir() / "arcadedb" / "log" -def render_logging_config(engine_text: str) -> str: - """The engine's logging config with the file log in ``logsDirectory``. +def console_enabled() -> bool: + """Whether the engine logs to the console (stdout/stderr) as well as to its log file. + + ``ARCADEDB_LOG_CONSOLE`` decides on every platform: ``1``, ``true``, ``yes`` or ``on`` turns the console handler on; ``0``, + ``false``, ``no`` or ``off`` turns it off. Unset (or any other value), it is on everywhere except Windows, where it is off + (see the module docstring for why). A ``java.util.logging.config.file`` the caller passes replaces all of this. + """ + value = os.environ.get(LOG_CONSOLE_ENV, "").strip().lower() + if value in ("1", "true", "yes", "on"): + return True + if value in ("0", "false", "no", "off"): + return False + return sys.platform != "win32" + + +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: + console = console_enabled() + return LOGGING_CONFIG_NAME if console else FILE_ONLY_CONFIG_NAME + + +def render_logging_config(engine_text: str, console: Optional[bool] = None) -> str: + """The engine's logging config with the file log in ``logsDirectory``, and without the console handler unless ``console``. The jar's own file hard-codes ``./log/arcadedb.log``, which lands in the working directory. The engine resolves ``${arcadedb.server.logsDirectory}`` in the pattern, and the argument that sets it is added by the caller. + ``console`` None means :func:`console_enabled`. """ - lines = [ - line - for line in engine_text.splitlines() - if not re.match(r"\s*java\.util\.logging\.FileHandler\.pattern\s*[=:]", line) - ] + if console is None: + console = console_enabled() + lines = [] + for line in engine_text.splitlines(): + if re.match(r"\s*java\.util\.logging\.FileHandler\.pattern\s*[=:]", line): + continue + if not console: + handlers = re.match(r"(\s*handlers\s*[=:]\s*)(.*)$", line) + if handlers: + kept = [ + h + for h in re.split(r"[,\s]+", handlers.group(2).strip()) + if h and h != CONSOLE_HANDLER + ] + line = f"{handlers.group(1)}{', '.join(kept)}" + elif re.match(r"\s*java\.util\.logging\.ConsoleHandler\.", line): + continue + lines.append(line) lines.append( "java.util.logging.FileHandler.pattern=" "${arcadedb.server.logsDirectory}/arcadedb.log" @@ -121,12 +168,14 @@ def usable_log_dir(log_dir: Path) -> Path: def write_logging_config(log_dir: Path, engine_text: str) -> None: - """Write ``logging.properties`` in ``log_dir`` (replaced atomically, and only when its text changed).""" - config = log_dir / LOGGING_CONFIG_NAME - rendered = render_logging_config(engine_text) + """Write the logging config in ``log_dir`` under :func:`logging_config_name` (replaced atomically, and only when its text changed).""" + console = console_enabled() + name = logging_config_name(console) + config = log_dir / name + rendered = render_logging_config(engine_text, console) try: if not config.exists() or config.read_text("iso-8859-1") != rendered: - tmp = log_dir / f"{LOGGING_CONFIG_NAME}.{os.getpid()}.tmp" + tmp = log_dir / f"{name}.{os.getpid()}.tmp" tmp.write_text(rendered, encoding="iso-8859-1", newline="\n") os.replace(tmp, config) except OSError as exc: diff --git a/src/arcadedb/_native/lib.py b/src/arcadedb/_native/lib.py index 984e799..b258d1d 100644 --- a/src/arcadedb/_native/lib.py +++ b/src/arcadedb/_native/lib.py @@ -79,7 +79,7 @@ def _log_isolate_args(user_args, log_dir) -> list: args.append(f"-Darcadedb.server.logsDirectory={posix}") if not any(a.startswith("-Djava.util.logging.config.file=") for a in user_args): args.append( - f"-Djava.util.logging.config.file={posix}/{_logdir.LOGGING_CONFIG_NAME}" + f"-Djava.util.logging.config.file={posix}/{_logdir.logging_config_name()}" ) return args @@ -102,7 +102,7 @@ def _heap_isolate_args(user_args) -> list: def _prepare_logging(user_args) -> list: - """Create the log directory, write its logging.properties and return the isolate arguments for it (see :func:`_log_isolate_args`).""" + """Create the log directory, write its logging config and return the isolate arguments for it (see :func:`_log_isolate_args`).""" global LOG_DIR_USED log_dir = _logdir.usable_log_dir(_logdir.default_log_dir()) _logdir.write_logging_config(log_dir, _logdir.NATIVE_ENGINE_LOG_PROPERTIES) diff --git a/src/arcadedb/jvm.py b/src/arcadedb/jvm.py index 77810df..7e26124 100644 --- a/src/arcadedb/jvm.py +++ b/src/arcadedb/jvm.py @@ -22,8 +22,8 @@ from . import aot as _aot from ._logdir import LOG_DIR_ENV as _LOG_DIR_ENV -from ._logdir import LOGGING_CONFIG_NAME as _LOGGING_CONFIG_NAME 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 usable_log_dir as _usable_log_dir from ._logdir import write_logging_config as _write_logging_config @@ -436,6 +436,14 @@ def start_jvm( then ``arcadedb/log``). A ``-Darcadedb.server.logsDirectory=`` or ``-Djava.util.logging.config.file=`` in ``jvm_args`` wins over it. + ARCADEDB_LOG_CONSOLE (optional) + ``1`` also logs to the console (stdout/stderr), ``0`` logs to the file + 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. + Needs to be set before the first JVM start. A + ``-Djava.util.logging.config.file=`` in ``jvm_args`` replaces it. + ARCADEDB_JVM_ERROR_FILE (optional) Path for JVM crash logs (default: ``hs_err_pid%p.log`` in the log directory above). ``-XX:ErrorFile=`` in ``jvm_args`` wins over it. @@ -837,7 +845,7 @@ def _build_jvm_args( arg.startswith("-Djava.util.logging.config.file=") for arg in merged_args ): merged_args.append( - f"-Djava.util.logging.config.file={log_dir_posix}/{_LOGGING_CONFIG_NAME}" + f"-Djava.util.logging.config.file={log_dir_posix}/{_logging_config_name()}" ) # Configure JVM crash log location (hs_err_pid*.log files) diff --git a/tests/test_log_dir.py b/tests/test_log_dir.py index 8119f8a..337c1b2 100644 --- a/tests/test_log_dir.py +++ b/tests/test_log_dir.py @@ -83,7 +83,7 @@ def test_default_logs_land_in_the_state_dir_not_the_cwd(tmp_path): assert home in log_dir.parents assert log_dir.name == "log" and log_dir.parent.name == "arcadedb" assert list(log_dir.glob("arcadedb.log*")), list(log_dir.iterdir()) - config = (log_dir / "logging.properties").read_text("iso-8859-1") + config = (log_dir / _logdir.logging_config_name()).read_text("iso-8859-1") assert "${arcadedb.server.logsDirectory}/arcadedb.log" in config assert "./log" not in config @@ -120,9 +120,10 @@ def test_args_never_name_the_working_directory(): # the expected directory comes from the same (cleared) environment the args were built in: on Windows the real # environment has LOCALAPPDATA and the cleared one falls back, so computing it outside the block would differ log_dir = _default_log_dir().as_posix() + config_name = _logdir.logging_config_name() assert not any("./log" in a for a in args) assert f"-Darcadedb.server.logsDirectory={log_dir}" in args - assert f"-Djava.util.logging.config.file={log_dir}/logging.properties" in args + assert f"-Djava.util.logging.config.file={log_dir}/{config_name}" in args assert f"-XX:ErrorFile={log_dir}/hs_err_pid%p.log" in args @@ -222,7 +223,8 @@ def test_arg_values_use_forward_slashes_on_every_platform(tmp_path): def test_native_isolate_arguments_name_the_log_dir(tmp_path): args = native_lib._log_isolate_args([], tmp_path) assert f"-Darcadedb.server.logsDirectory={tmp_path.as_posix()}" in args - config = f"-Djava.util.logging.config.file={tmp_path.as_posix()}/logging.properties" + name = _logdir.logging_config_name() + config = f"-Djava.util.logging.config.file={tmp_path.as_posix()}/{name}" assert config in args assert not any("./log" in a for a in args) @@ -240,7 +242,9 @@ def test_native_user_isolate_arguments_win_over_the_log_defaults(tmp_path): def test_native_engine_log_config_renders_like_the_jvm_one(): - rendered = _logdir.render_logging_config(_logdir.NATIVE_ENGINE_LOG_PROPERTIES) + rendered = _logdir.render_logging_config( + _logdir.NATIVE_ENGINE_LOG_PROPERTIES, console=True + ) assert "./log" not in rendered assert rendered.count("FileHandler.pattern") == 1 assert "${arcadedb.server.logsDirectory}/arcadedb.log" in rendered diff --git a/tests/test_log_redirect.py b/tests/test_log_redirect.py new file mode 100644 index 0000000..a126f1e --- /dev/null +++ b/tests/test_log_redirect.py @@ -0,0 +1,261 @@ +"""A host that redirects fd 1 and 2 after the library started must not get engine log text 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 +``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. +""" + +import json +import os +import re +import subprocess # nosec B404 - test-controlled child process +import sys +from pathlib import Path + +import pytest + +from arcadedb import _logdir + +# One engine log line as the file and console formatters write it: date, time with milliseconds, level. +LOG_LINE = re.compile( + rb"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} " + rb"(?:SEVERE|WARNING|INFO|CONFIG|FINE|FINER|FINEST)\b" +) + +CHILD = """ +import json +import os +import sys +import time + +import arcadedb + +mode, data_dir, sink, result = sys.argv[1:5] + +# 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")) +warm.command("sql", "CREATE DOCUMENT TYPE Warm") +warm.close() + +if mode == "redirect": + # what pytest's fd capture, a service or an embedding application does + fd = os.open(sink, os.O_WRONLY | os.O_CREAT | os.O_TRUNC) + os.dup2(fd, 1) + os.dup2(fd, 2) + os.close(fd) + +db_path = os.path.join(data_dir, "db") +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( + "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) + +with open(result, "w") as out: + json.dump({"count": count, "neighbors": len(neighbors)}, 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).""" + data_dir = tmp_path / "data" + data_dir.mkdir() + log_dir = tmp_path / "log" + sink = tmp_path / "sink.txt" + result = tmp_path / "result.json" + env = { + k: v + for k, v in os.environ.items() + if k not in ("ARCADEDB_LOG_CONSOLE", "ARCADEDB_LOG_DIR") + } + env["ARCADEDB_LOG_DIR"] = str(log_dir) + 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)], + env=env, + capture_output=True, + timeout=600, + ) + sink_text = sink.read_bytes() if sink.exists() else b"" + assert proc.returncode == 0, ( + proc.stdout.decode(errors="replace") + + proc.stderr.decode(errors="replace") + + sink_text.decode(errors="replace") + ) + 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.""" + found = [] + for path in sorted(p for p in root.rglob("*") if p.is_file()): + match = LOG_LINE.search(path.read_bytes()) + if match: + found.append((str(path.relative_to(root)), match.group(0))) + return found + + +def _log_file_text(log_dir: Path) -> bytes: + return b"".join(p.read_bytes() for p in sorted(log_dir.glob("arcadedb.log*"))) + + +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) == [] + # 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()) + + +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)) + + +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 + assert LOG_LINE.search(console), console[:500] + assert _log_lines_in_files(data_dir) == [] + assert LOG_LINE.search(_log_file_text(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 + assert LOG_LINE.search(console) is None, console[:500] + assert LOG_LINE.search(_log_file_text(log_dir)) + + +@pytest.mark.parametrize( + ("platform", "value", "expected"), + [ + ("linux", None, True), + ("darwin", None, True), + ("win32", None, False), + ("win32", "1", True), + ("win32", "true", True), + ("win32", " On ", True), + ("linux", "0", False), + ("linux", "false", False), + ("darwin", "no", False), + ("linux", "", True), + ("win32", "", False), + ("win32", "maybe", False), + ("linux", "maybe", True), + ], +) +def test_console_default_by_platform_and_env(monkeypatch, platform, value, expected): + monkeypatch.setattr(sys, "platform", platform) + monkeypatch.delenv("ARCADEDB_LOG_CONSOLE", raising=False) + if value is not None: + monkeypatch.setenv("ARCADEDB_LOG_CONSOLE", value) + assert _logdir.console_enabled() is expected + assert _logdir.logging_config_name() == ( + "logging.properties" if expected else "logging-file-only.properties" + ) + + +def test_render_without_the_console_keeps_only_the_file_handler(): + engine = ( + "handlers = java.util.logging.ConsoleHandler, java.util.logging.FileHandler\n" + ".level = INFO\n" + "java.util.logging.ConsoleHandler.level = INFO\n" + "java.util.logging.ConsoleHandler.formatter = com.arcadedb.utility.AnsiLogFormatter\n" + "java.util.logging.FileHandler.pattern=./log/arcadedb.log\n" + "java.util.logging.FileHandler.level = INFO\n" + ) + plain = _logdir.render_logging_config(engine, console=False) + assert "ConsoleHandler" not in plain + assert "handlers = java.util.logging.FileHandler\n" in plain + assert "java.util.logging.FileHandler.level = INFO" in plain + assert ".level = INFO" in plain + assert "${arcadedb.server.logsDirectory}/arcadedb.log" in plain + with_console = _logdir.render_logging_config(engine, console=True) + assert ( + "handlers = java.util.logging.ConsoleHandler, java.util.logging.FileHandler" + in with_console + ) + assert "java.util.logging.ConsoleHandler.formatter" in with_console + + +def test_each_console_setting_has_its_own_config_file(tmp_path, monkeypatch): + engine = _logdir.NATIVE_ENGINE_LOG_PROPERTIES + monkeypatch.setenv("ARCADEDB_LOG_CONSOLE", "1") + _logdir.write_logging_config(tmp_path, engine) + monkeypatch.setenv("ARCADEDB_LOG_CONSOLE", "0") + _logdir.write_logging_config(tmp_path, engine) + full = (tmp_path / "logging.properties").read_text("iso-8859-1") + file_only = (tmp_path / "logging-file-only.properties").read_text("iso-8859-1") + assert "ConsoleHandler" in full + assert "ConsoleHandler" not in file_only + assert "FileHandler" in file_only + + +def test_both_builds_point_the_engine_at_the_config_for_the_setting( + tmp_path, monkeypatch +): + from arcadedb._native import lib as native_lib + from arcadedb.jvm import _build_jvm_args + + monkeypatch.setattr(sys, "platform", "win32") + monkeypatch.delenv("ARCADEDB_LOG_CONSOLE", raising=False) + jvm_args = _build_jvm_args( + heap_size="4g", disable_xml_limits=False, jvm_args=None, log_dir=tmp_path + ) + native_args = native_lib._log_isolate_args([], tmp_path) + expected = ( + f"-Djava.util.logging.config.file={tmp_path.as_posix()}" + "/logging-file-only.properties" + ) + assert expected in jvm_args + assert expected in native_args + monkeypatch.setenv("ARCADEDB_LOG_CONSOLE", "1") + expected = ( + f"-Djava.util.logging.config.file={tmp_path.as_posix()}/logging.properties" + ) + assert expected in _build_jvm_args( + heap_size="4g", disable_xml_limits=False, jvm_args=None, log_dir=tmp_path + ) + assert expected in native_lib._log_isolate_args([], tmp_path)