chore: Delegate log events to Python logger (#65)

- This allows Python to configure their own appenders in Python
  (and use the standard Python appenders), abeit at a performance
  penalty. However, since DEBUG and lower should not be used
  when performance is required, log messages are produced only
  when solving started/ended, which is infrequent.

- Tracking the log level of 'timefold.solver' would work, except
we need to also track its parent logger, since their level affect
the effective log level. Thus, we need
to 'refresh' the log level whenever solving starts (which
is the only time the Java side would emit log messages).

Author: Christopher-Chianelli

tests/test_logging.py

@@ -0,0 +1,129 @@
+import logging
+from timefold.solver import *
+from timefold.solver.domain import *
+from timefold.solver.config import *
+from timefold.solver.score import *
+
+from dataclasses import dataclass, field
+from typing import Annotated, List
+
+
+@planning_entity
+@dataclass
+class Entity:
+    code: Annotated[str, PlanningId]
+    value: Annotated[int, PlanningVariable] = field(default=None, compare=False)
+
+
+@constraint_provider
+def my_constraints(constraint_factory: ConstraintFactory):
+    return [
+        constraint_factory.for_each(Entity)
+        .reward(SimpleScore.ONE, lambda entity: entity.value)
+        .as_constraint('Maximize value'),
+    ]
+
+
+@planning_solution
+@dataclass
+class Solution:
+    entities: Annotated[List[Entity], PlanningEntityCollectionProperty]
+    value_range: Annotated[List[int], ValueRangeProvider]
+    score: Annotated[SimpleScore, PlanningScore] = field(default=None)
+
+    def __str__(self) -> str:
+        return str(self.entities)
+
+
+def assert_in_logs(log_messages: list[str], message: str):
+    for log_message in log_messages:
+        if message in log_message:
+            return
+    raise AssertionError(f'Expected message {message} in {log_messages}, but it was not found.')
+
+def test_log_events_are_forwarded(caplog):
+    with caplog.at_level(logging.INFO, logger="timefold.solver"):
+        solver_config = SolverConfig(
+            solution_class=Solution,
+            entity_class_list=[Entity],
+            score_director_factory_config=ScoreDirectorFactoryConfig(
+                constraint_provider_function=my_constraints,
+            ),
+            termination_config=TerminationConfig(
+                best_score_limit='9'
+            )
+        )
+        solver_factory = SolverFactory.create(solver_config)
+        solver = solver_factory.build_solver(SolverConfigOverride(
+            termination_config=TerminationConfig(
+                best_score_limit='3'
+            )
+        ))
+        problem = Solution([Entity('A')], [1, 2, 3])
+        solver.solve(problem)
+        log_messages = [rec.message for rec in caplog.records]
+        # INFO
+        assert_in_logs(log_messages, 'Solving started')
+        # INFO
+        assert_in_logs(log_messages, 'Solving ended')
+
+
+def test_support_changing_log_levels(caplog):
+    with caplog.at_level(logging.DEBUG, logger="timefold.solver"):
+        solver_config = SolverConfig(
+            solution_class=Solution,
+            entity_class_list=[Entity],
+            score_director_factory_config=ScoreDirectorFactoryConfig(
+                constraint_provider_function=my_constraints,
+            ),
+            termination_config=TerminationConfig(
+                best_score_limit='9'
+            )
+        )
+        solver_factory = SolverFactory.create(solver_config)
+        solver = solver_factory.build_solver(SolverConfigOverride(
+            termination_config=TerminationConfig(
+                best_score_limit='3'
+            )
+        ))
+        problem = Solution([Entity('A')], [1, 2, 3])
+        solver.solve(problem)
+        log_messages = [rec.message for rec in caplog.records]
+        # INFO
+        assert_in_logs(log_messages, 'Solving started')
+        # DEBUG
+        assert_in_logs(log_messages, 'CH step (0)')
+        # INFO
+        assert_in_logs(log_messages, 'Solving ended')
+
+
+def test_support_trace_logs(caplog):
+    # Python has no logging.TRACE, logging.DEBUG = 10, so TRACE = 5
+    with caplog.at_level(5, logger="timefold.solver"):
+        solver_config = SolverConfig(
+            solution_class=Solution,
+            entity_class_list=[Entity],
+            score_director_factory_config=ScoreDirectorFactoryConfig(
+                constraint_provider_function=my_constraints,
+            ),
+            termination_config=TerminationConfig(
+                best_score_limit='9'
+            )
+        )
+        solver_factory = SolverFactory.create(solver_config)
+        solver = solver_factory.build_solver(SolverConfigOverride(
+            termination_config=TerminationConfig(
+                best_score_limit='3'
+            )
+        ))
+        problem = Solution([Entity('A')], [1, 2, 3])
+        solver.solve(problem)
+        log_messages = [rec.message for rec in caplog.records]
+        # INFO
+        assert_in_logs(log_messages, 'Solving started')
+        # DEBUG
+        assert_in_logs(log_messages, 'CH step (0)')
+        # TRACE/5
+        assert_in_logs(log_messages, 'Move index (1)')
+        # INFO
+        assert_in_logs(log_messages, 'Solving ended')

timefold-solver-python-core/pom.xml

@@ -35,6 +35,10 @@
       <groupId>ch.qos.logback</groupId>
       <artifactId>logback-classic</artifactId>
     </dependency>
+    <dependency>
+      <groupId>ch.qos.logback</groupId>
+      <artifactId>logback-core</artifactId>
+    </dependency>
     <dependency>
       <groupId>org.slf4j</groupId>
       <artifactId>slf4j-api</artifactId>

timefold-solver-python-core/src/main/java/ai/timefold/solver/python/logging/PythonDelegateAppender.java

@@ -0,0 +1,22 @@
+package ai.timefold.solver.python.logging;
+
+import java.util.function.Consumer;
+
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.AppenderBase;
+
+public class PythonDelegateAppender extends AppenderBase<ILoggingEvent> {
+    private static Consumer<PythonLoggingEvent> logEventConsumer;
+
+    public static void setLogEventConsumer(Consumer<PythonLoggingEvent> logEventConsumer) {
+        PythonDelegateAppender.logEventConsumer = logEventConsumer;
+    }
+
+    @Override
+    protected void append(ILoggingEvent eventObject) {
+        logEventConsumer.accept(
+                new PythonLoggingEvent(
+                        PythonLogLevel.fromJavaLevel(eventObject.getLevel()),
+                        eventObject.getFormattedMessage()));
+    }
+}

timefold-solver-python-core/src/main/java/ai/timefold/solver/python/logging/PythonLogLevel.java

@@ -8,6 +8,7 @@ public enum PythonLogLevel {
     WARNING(30, Level.WARN),
     INFO(20, Level.INFO),
     DEBUG(10, Level.DEBUG),
+    TRACE(5, Level.TRACE),
     NOTSET(0, Level.INFO);
 
     final int pythonLevelNumber;
@@ -26,6 +27,24 @@ public Level getJavaLogLevel() {
         return javaLogLevel;
     }
 
+    public static PythonLogLevel fromJavaLevel(Level level) {
+        // Check INFO and ERROR first, since they have multiple corresponding
+        // Python levels
+        if (level.equals(Level.INFO)) {
+            return INFO;
+        } else if (level.equals(Level.ERROR)) {
+            return ERROR;
+        } else {
+            int levelNumber = level.toInt();
+            for (PythonLogLevel pythonLogLevel : PythonLogLevel.values()) {
+                if (pythonLogLevel.getJavaLogLevel().toInt() == levelNumber) {
+                    return pythonLogLevel;
+                }
+            }
+            throw new IllegalStateException("Unmatched log level (" + level + ") with level number (" + level.toInt() + ").");
+        }
+    }
+
     public static PythonLogLevel fromPythonLevelNumber(int levelNumber) {
         PythonLogLevel bestMatch = PythonLogLevel.CRITICAL;
         int bestMatchLevelNumber = 50;

timefold-solver-python-core/src/main/java/ai/timefold/solver/python/logging/PythonLoggingEvent.java

@@ -0,0 +1,4 @@
+package ai.timefold.solver.python.logging;
+
+public record PythonLoggingEvent(PythonLogLevel level, String message) {
+}

timefold-solver-python-core/src/main/java/ai/timefold/solver/python/logging/PythonLoggingToLogbackAdapter.java

@@ -2,32 +2,14 @@
 
 import org.slf4j.LoggerFactory;
 
-import ch.qos.logback.classic.Level;
 import ch.qos.logback.classic.Logger;
 import ch.qos.logback.classic.LoggerContext;
 
 public class PythonLoggingToLogbackAdapter {
+    private static final Logger LOGGER = ((LoggerContext) LoggerFactory.getILoggerFactory()).getLogger("ai.timefold");
 
-    private static Logger getLogger(String loggerName) {
-        LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
-        return loggerContext.getLogger(loggerName);
-    }
-
-    public static void setLevel(String loggerName, int logLevel) {
-        Logger logger = getLogger(loggerName);
+    public static void setLevel(int logLevel) {
         PythonLogLevel pythonLogLevel = PythonLogLevel.fromPythonLevelNumber(logLevel);
-        logger.setLevel(pythonLogLevel.getJavaLogLevel());
-    }
-
-    public static boolean isEnabledFor(String loggerName, int logLevel) {
-        Logger logger = getLogger(loggerName);
-        PythonLogLevel pythonLogLevel = PythonLogLevel.fromPythonLevelNumber(logLevel);
-        return logger.isEnabledFor(pythonLogLevel.getJavaLogLevel());
-    }
-
-    public static int getEffectiveLevel(String loggerName) {
-        Logger logger = getLogger(loggerName);
-        Level effectiveLogLevel = logger.getEffectiveLevel();
-        return effectiveLogLevel.levelInt / 1000;
+        LOGGER.setLevel(pythonLogLevel.getJavaLogLevel());
     }
 }

timefold-solver-python-core/src/main/python/_jpype_type_conversions.py

@@ -13,6 +13,16 @@ def defineConstraints(self, constraint_factory):
         return self.delegate(constraint_factory)
 
 
+@JImplements('java.util.function.Consumer', deferred=True)
+class PythonConsumer:
+    def __init__(self, delegate):
+        self.delegate = delegate
+
+    @JOverride
+    def accept(self, item):
+        return self.delegate(item)
+
+
 @JImplements('java.util.function.Supplier', deferred=True)
 class PythonSupplier:
     def __init__(self, delegate):

timefold-solver-python-core/src/main/python/_solver.py

@@ -1,4 +1,5 @@
 from ._problem_change import ProblemChange, ProblemChangeWrapper
+from ._timefold_java_interop import update_log_level
 from typing import TypeVar, TYPE_CHECKING, Generic, Callable
 from datetime import timedelta
 from jpype import JClass, JImplements, JOverride
@@ -102,6 +103,7 @@ def solve(self, problem: Solution_):
             raise ValueError(
                 f'The problem ({problem}) is not an instance of the @planning_solution class ({self._solution_class})'
             )
+        update_log_level()
         try:
             java_solution = self._delegate.solve(java_problem)
         except PythonBaseException as e:

timefold-solver-python-core/src/main/python/_solver_manager.py

@@ -2,6 +2,7 @@
 from .config import SolverConfigOverride
 from ._solver_factory import SolverFactory
 from ._future import wrap_future
+from ._timefold_java_interop import update_log_level
 
 from typing import Awaitable, TypeVar, Generic, Callable, TYPE_CHECKING
 from datetime import timedelta
@@ -317,6 +318,7 @@ def run(self) -> SolverJob[Solution_, ProblemId_]:
         SolverJob
             The `SolverJob` built from this `SolverJobBuilder`.
         """
+        update_log_level()
         return SolverJob(self._delegate.run())
 
 

timefold-solver-python-core/src/main/python/_timefold_java_interop.py

@@ -1,16 +1,20 @@
+import logging
 import pathlib
 import jpype
 import jpype.imports
 from jpype.types import *
 import importlib.resources
 from typing import cast, TypeVar, Callable, Union, TYPE_CHECKING, Any
-from ._jpype_type_conversions import PythonSupplier, ConstraintProviderFunction
+from ._jpype_type_conversions import PythonSupplier, ConstraintProviderFunction, PythonConsumer
 
 if TYPE_CHECKING:
     # These imports require a JVM to be running, so only import if type checking
     from java.lang import ClassLoader
     from ai.timefold.solver.core.api.score.stream import (Constraint as _Constraint,
                                                           ConstraintFactory as _ConstraintFactory)
+    from ai.timefold.solver.python import PythonLoggingEvent
+
+logger = logging.getLogger('timefold.solver')
 
 Solution_ = TypeVar('Solution_')
 ProblemId_ = TypeVar('ProblemId_')
@@ -49,7 +53,7 @@ def extract_timefold_jars() -> list[str]:
             if p.name.endswith(".jar")] + enterprise_dependencies
 
 
-def init(*args, path: list[str] = None, include_timefold_jars: bool = True, log_level='INFO') -> None:
+def init(*args, path: list[str] = None, include_timefold_jars: bool = True) -> None:
     """
     Most users will never need to call this method.
     Only call this method if you are using other Java libraries.
@@ -66,10 +70,9 @@ def init(*args, path: list[str] = None, include_timefold_jars: bool = True, log_
     include_timefold_jars : bool, optional
         If the Timefold dependencies should be added to `path`.
         Defaults to True.
-    log_level : str
-        The logging level to use.
     """
     from _jpyinterpreter import init
+
     if jpype.isJVMStarted():  # noqa
         raise RuntimeError('JVM already started. Maybe call init before timefold.solver.types imports?')
     if path is None:
@@ -78,11 +81,23 @@ def init(*args, path: list[str] = None, include_timefold_jars: bool = True, log_
     if include_timefold_jars:
         path = path + extract_timefold_jars()
     if len(args) == 0:
-        args = (jpype.getDefaultJVMPath(), '-Dlogback.level.ai.timefold={}'.format(log_level))  # noqa
-    else:
-        args = args + ('-Dlogback.level.ai.timefold={}'.format(log_level),)
+        args = [jpype.getDefaultJVMPath()]
     init(*args, path=path, include_translator_jars=False)
 
+    from ai.timefold.solver.python.logging import PythonLoggingToLogbackAdapter, PythonDelegateAppender
+    PythonDelegateAppender.setLogEventConsumer(PythonConsumer(forward_logging_events))
+    update_log_level()
+
+
+def update_log_level() -> None:
+    from ai.timefold.solver.python.logging import PythonLoggingToLogbackAdapter
+    PythonLoggingToLogbackAdapter.setLevel(logger.getEffectiveLevel())
+
+
+def forward_logging_events(event: 'PythonLoggingEvent') -> None:
+    logger.log(event.level().getPythonLevelNumber(),
+               event.message())
+
 
 def ensure_init():
     """