Windows: engine logs go to the file only, so redirecting fd 1/2 cannot put log text in database files

.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

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

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;

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. */

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",

src/arcadedb/_logdir.py

@@ -6,20 +6,31 @@
 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
 import re
 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:

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)

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)

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