Repository: NTNU-IHB/PythonFMU (python)

Issue:
Enhance logging
FMI defines a logger mechanism. Python itself has a standard logging library. A good enhancement would be to redirect the Python logger to the FMI one.

In addition, the support for the debug log flag at FMU instantiation should be added.

Pull request description:
Support logging
`self.log("")` will always print
`self.log("", debug=True)` will print if FMI `debugLogging` is set

Closes #35
Closes #85 

Patch:
diff --git a/pythonfmu/builder.py b/pythonfmu/builder.py
index 822bfcd..bd4a219 100644
--- a/pythonfmu/builder.py
+++ b/pythonfmu/builder.py
@@ -3,7 +3,6 @@ import argparse
 import importlib
 import itertools
 import logging
-import platform
 import re
 import shutil
 import sys
@@ -13,7 +12,7 @@ from pathlib import Path
 from typing import Iterable, Optional, Tuple, Union
 from xml.dom.minidom import parseString
 from xml.etree.ElementTree import Element, SubElement, tostring
-
+from .osutil import get_lib_extension, get_platform
 from ._version import __version__
 from .fmi2slave import FMI2_MODEL_OPTIONS, Fmi2Slave
 
@@ -23,24 +22,10 @@ HERE = Path(__file__).parent
 logger = logging.getLogger(__name__)
 
 
-def get_platform() -> str:
-    """Get FMU binary platform folder name."""
-    system = platform.system()
-    is_64bits = sys.maxsize > 2 ** 32
-    platforms = {"Windows": "win", "Linux": "linux", "Darwin": "darwin"}
-    return platforms.get(system, "unknown") + "64" if is_64bits else "32"
-
-
-def get_lib_extension() -> str:
-    """Get FMU library platform extension."""
-    platforms = {"Darwin": "dylib", "Linux": "so", "Windows": "dll"}
-    return platforms.get(platform.system(), "")
-
-
 def get_class_name(file_name: Path) -> str:
     with open(str(file_name), 'r') as file:
         data = file.read()
-        return re.search('class (\w+)\(\s*Fmi2Slave\s*\)\s*:', data).group(1)
+        return re.search(r'class (\w+)\(\s*Fmi2Slave\s*\)\s*:', data).group(1)
 
 
 class ModelDescriptionFetcher:
diff --git a/pythonfmu/enums.py b/pythonfmu/enums.py
index 3557150..143c065 100644
--- a/pythonfmu/enums.py
+++ b/pythonfmu/enums.py
@@ -1,5 +1,5 @@
 """FMI enumerations"""
-from enum import Enum
+from enum import Enum, IntEnum
 
 
 class Fmi2Causality(Enum):
@@ -22,3 +22,12 @@ class Fmi2Variability(Enum):
     tunable = 2
     discrete = 3
     continuous = 4
+
+
+class Fmi2Status(IntEnum):
+    ok = 0
+    warning = 1
+    discard = 2
+    error = 3
+    fatal = 4
+
diff --git a/pythonfmu/fmi2slave.py b/pythonfmu/fmi2slave.py
index c52563e..d6b8245 100644
--- a/pythonfmu/fmi2slave.py
+++ b/pythonfmu/fmi2slave.py
@@ -3,12 +3,15 @@ import json
 import datetime
 from abc import ABC, abstractmethod
 from collections import OrderedDict, namedtuple
+from pathlib import Path
 from typing import Any, ClassVar, Dict, List, Optional
 from uuid import uuid1
 from xml.etree.ElementTree import Element, SubElement
+from ctypes import cdll, c_char_p, c_void_p, c_int, c_bool
 
+from .osutil import get_lib_extension, get_platform
 from ._version import __version__ as VERSION
-from .enums import Fmi2Causality, Fmi2Initial, Fmi2Variability
+from .enums import Fmi2Status, Fmi2Causality, Fmi2Initial, Fmi2Variability
 from .variables import Boolean, Integer, Real, ScalarVariable, String
 
 ModelOptions = namedtuple("ModelOptions", ["name", "value", "cli"])
@@ -39,7 +42,10 @@ class Fmi2Slave(ABC):
         self.vars = OrderedDict()
         self.instance_name = kwargs["instance_name"]
         self.resources = kwargs.get("resources", None)
+        self.logger = kwargs.get("logger", None)
         self.visible = kwargs.get("visible", False)
+        self.__lib = None
+        self.__lib_error = False
 
         if self.__class__.modelName is None:
             self.__class__.modelName = self.__class__.__name__
@@ -263,3 +269,29 @@ class Fmi2Slave(ABC):
     @staticmethod
     def _fmu_state_from_bytes(state: bytes) -> Dict[str, Any]:
         return json.loads(state.decode("utf-8"))
+
+    def log(self, msg: str, status: Fmi2Status = Fmi2Status.ok, category: str = "", debug: bool = False):
+        """Log a message to the FMU logger.
+        
+        Args:
+            msg (str) : Log message
+            status (Fmi2Status) : Optional, message status (default ok)
+            category (str) : Optional, message category (default "")
+            debug (bool) : Optional, is this a debug message (default False)
+        """
+        if self.logger is not None and self.resources is not None:
+            if self.__lib is None and not self.__lib_error:
+                library_path = Path(self.resources).parent / "binaries" / get_platform() / (self.modelName + "." + get_lib_extension())
+                try:
+                    self.__lib = cdll.LoadLibrary(str(library_path))
+                except:
+                    self.__lib_error = True
+                    print(f"Warning. Unable to setup logging for FMU instance: {self.instance_name}")
+            if not self.__lib_error:
+                self.__lib.pylog(
+                    c_void_p(self.logger),
+                    c_int(int(status)),
+                    c_char_p(category.encode("utf-8")),
+                    c_char_p(msg.encode("utf-8")),
+                    c_bool(debug)
+                )
diff --git a/pythonfmu/osutil.py b/pythonfmu/osutil.py
new file mode 100644
index 0000000..bb55c20
--- /dev/null
+++ b/pythonfmu/osutil.py
@@ -0,0 +1,17 @@
+import sys
+import platform
+
+
+def get_platform() -> str:
+    """Get FMU binary platform folder name."""
+    system = platform.system()
+    is_64bits = sys.maxsize > 2 ** 32
+    platforms = {"Windows": "win", "Linux": "linux", "Darwin": "darwin"}
+    return platforms.get(system, "unknown") + "64" if is_64bits else "32"
+
+
+def get_lib_extension() -> str:
+    """Get FMU library platform extension."""
+    platforms = {"Darwin": "dylib", "Linux": "so", "Windows": "dll"}
+    return platforms.get(platform.system(), "")
+
diff --git a/pythonfmu/pythonfmu-export/CMakeLists.txt b/pythonfmu/pythonfmu-export/CMakeLists.txt
index b4c4740..67b73f8 100644
--- a/pythonfmu/pythonfmu-export/CMakeLists.txt
+++ b/pythonfmu/pythonfmu-export/CMakeLists.txt
@@ -47,6 +47,7 @@ endif ()
 include_directories(${CMAKE_CURRENT_SOURCE_DIR}/headers)
 
 set(sources
+        cpp/pylog.cpp
         cpp/cppfmu_cs.cpp
         cpp/fmi_functions.cpp
         cpp/PySlaveInstance.cpp
diff --git a/pythonfmu/pythonfmu-export/cpp/PySlaveInstance.cpp b/pythonfmu/pythonfmu-export/cpp/PySlaveInstance.cpp
index 0824164..100edba 100644
--- a/pythonfmu/pythonfmu-export/cpp/PySlaveInstance.cpp
+++ b/pythonfmu/pythonfmu-export/cpp/PySlaveInstance.cpp
@@ -44,9 +44,10 @@ inline void py_safe_run(const std::function<void(PyGILState_STATE gilState)>& f)
     PyGILState_Release(gil_state);
 }
 
-PySlaveInstance::PySlaveInstance(std::string instanceName, std::string resources, const bool visible)
+PySlaveInstance::PySlaveInstance(std::string instanceName, std::string resources, const cppfmu::Logger& logger, const bool visible)
     : instanceName_(std::move(instanceName))
     , resources_(std::move(resources))
+    , logger_(logger)
     , visible_(visible)
 
 {
@@ -100,9 +101,10 @@ void PySlaveInstance::initialize(PyGILState_STATE gilState)
     Py_XDECREF(pInstance_);
 
     PyObject* args = PyTuple_New(0);
-    PyObject* kwargs = Py_BuildValue("{sssssi}",
+    PyObject* kwargs = Py_BuildValue("{ss,ss,sL,si}",
         "instance_name", instanceName_.c_str(),
         "resources", resources_.c_str(),
+        "logger", &logger_,
         "visible", visible_);
     pInstance_ = PyObject_Call(pClass_, args, kwargs);
     Py_DECREF(args);
@@ -480,7 +482,7 @@ cppfmu::UniquePtr<cppfmu::SlaveInstance> CppfmuInstantiateSlave(
     cppfmu::FMIBoolean visible,
     cppfmu::FMIBoolean,
     cppfmu::Memory memory,
-    const cppfmu::Logger&)
+    const cppfmu::Logger& logger)
 {
 
     auto resources = std::string(fmuResourceLocation);
@@ -499,5 +501,5 @@ cppfmu::UniquePtr<cppfmu::SlaveInstance> CppfmuInstantiateSlave(
     }
 
     return cppfmu::AllocateUnique<pythonfmu::PySlaveInstance>(
-        memory, instanceName, resources, visible);
+        memory, instanceName, resources, logger, visible);
 }
diff --git a/pythonfmu/pythonfmu-export/cpp/pylog.cpp b/pythonfmu/pythonfmu-export/cpp/pylog.cpp
new file mode 100644
index 0000000..8d5f46c
--- /dev/null
+++ b/pythonfmu/pythonfmu-export/cpp/pylog.cpp
@@ -0,0 +1,17 @@
+
+#include "cppfmu/cppfmu_common.hpp"
+
+extern "C" {
+
+/* Log a message from Python to the FMU logger */
+void pylog(void* logPtr, int status, const char* category, const char* msg, bool debug)
+{
+    auto logger = ((cppfmu::Logger*) logPtr);
+    if (!debug) {
+        logger->Log((fmi2Status) status, category, msg);
+    } else {
+        logger->DebugLog((fmi2Status) status, category, msg);
+    }
+}
+
+}
diff --git a/pythonfmu/pythonfmu-export/headers/pythonfmu/PySlaveInstance.hpp b/pythonfmu/pythonfmu-export/headers/pythonfmu/PySlaveInstance.hpp
index 1356f2f..498c7f9 100644
--- a/pythonfmu/pythonfmu-export/headers/pythonfmu/PySlaveInstance.hpp
+++ b/pythonfmu/pythonfmu-export/headers/pythonfmu/PySlaveInstance.hpp
@@ -15,7 +15,7 @@ class PySlaveInstance : public cppfmu::SlaveInstance
 {
 
 public:
-    PySlaveInstance(std::string instanceName, std::string resources, bool visible);
+    PySlaveInstance(std::string instanceName, std::string resources, const cppfmu::Logger& logger, bool visible);
 
     void initialize(PyGILState_STATE gilState);
 
@@ -53,6 +53,7 @@ private:
     const bool visible_;
     const std::string instanceName_;
     const std::string resources_;
+    const cppfmu::Logger& logger_;
 
     mutable std::vector<PyObject*> strBuffer;
 


Test patch:
diff --git a/pythonfmu/tests/test_fmi2slave.py b/pythonfmu/tests/test_fmi2slave.py
index 940d550..71de8e2 100644
--- a/pythonfmu/tests/test_fmi2slave.py
+++ b/pythonfmu/tests/test_fmi2slave.py
@@ -3,15 +3,9 @@ import pytest
 from pythonfmu import Fmi2Slave, Boolean, Integer, Real, String
 from pythonfmu import __version__ as VERSION
 
-# TODO test xml
+from .utils import FMI2PY, PY2FMI
 
-FMI2PY = dict((
-    (Boolean, bool),
-    (Integer, int),
-    (Real, float),
-    (String, str)
-))
-PY2FMI = dict([(v, k) for k, v in FMI2PY.items()])
+# TODO test xml
 
 
 @pytest.mark.parametrize("model", ["theModelName", None])
@@ -67,10 +61,10 @@ def test_Fmi2Slave_getters(fmi_type, value):
 
     slave = Slave(instance_name="slaveInstance")
     if type(value) is py_type:
-        assert getattr(slave, f"get_{fmi_type_name}")([0, ]) == [value, ]
+        assert getattr(slave, f"get_{fmi_type_name}")([0]) == [value]
     else:
         with pytest.raises(TypeError):
-            getattr(slave, f"get_{fmi_type_name}")([0, ])
+            getattr(slave, f"get_{fmi_type_name}")([0])
 
 
 @pytest.mark.parametrize("fmi_type", FMI2PY)
@@ -98,9 +92,9 @@ def test_Fmi2Slave_setters(fmi_type, value):
 
     if type(value) is py_type:
         set_method = getattr(slave, f"set_{fmi_type_name}")
-        set_method([0, ], [value, ])
-        assert getattr(slave, f"get_{fmi_type_name}")([0, ]) == [value, ]
+        set_method([0], [value])
+        assert getattr(slave, f"get_{fmi_type_name}")([0]) == [value, ]
     else:
         set_method = getattr(slave, f"set_{fmi_type_name}")
         with pytest.raises(TypeError):
-            set_method([0, ], [value, ])
+            set_method([0], [value])
diff --git a/pythonfmu/tests/test_integration.py b/pythonfmu/tests/test_integration.py
index 3fe98ca..0445d60 100644
--- a/pythonfmu/tests/test_integration.py
+++ b/pythonfmu/tests/test_integration.py
@@ -214,16 +214,16 @@ def test_integration_set(tmp_path):
     for key, value in to_test.items():
         var = variables[key]
         if var.type == pyfmi.fmi.FMI2_INTEGER:
-            model.set_integer([var.value_reference], [value, ])
+            model.set_integer([var.value_reference], [value])
             model_value = model.get_integer([var.value_reference])[0]
         elif var.type == pyfmi.fmi.FMI2_REAL:
-            model.set_real([var.value_reference], [value, ])
+            model.set_real([var.value_reference], [value])
             model_value = model.get_real([var.value_reference])[0]
         elif var.type == pyfmi.fmi.FMI2_BOOLEAN:
-            model.set_boolean([var.value_reference], [value, ])
+            model.set_boolean([var.value_reference], [value])
             model_value = model.get_boolean([var.value_reference])[0]
         elif var.type == pyfmi.fmi.FMI2_STRING:
-            model.set_string([var.value_reference], [value, ])
+            model.set_string([var.value_reference], [value])
             model_value = model.get_string([var.value_reference])[0]
         else:
             pytest.xfail("Unsupported type")
diff --git a/pythonfmu/tests/test_logger.py b/pythonfmu/tests/test_logger.py
new file mode 100644
index 0000000..4cf1c9d
--- /dev/null
+++ b/pythonfmu/tests/test_logger.py
@@ -0,0 +1,86 @@
+import itertools
+import pytest
+from unittest.mock import call, MagicMock
+
+from pythonfmu.builder import FmuBuilder
+from pythonfmu.enums import Fmi2Status
+
+pytestmark = pytest.mark.skipif(
+    not FmuBuilder.has_binary(), reason="No binary available for the current platform."
+)
+
+
+@pytest.mark.integration
+@pytest.mark.parametrize("debug_logging", [True, False])
+def test_logger(tmp_path, debug_logging):
+    fmpy = pytest.importorskip(
+        "fmpy", reason="fmpy is not available for testing the produced FMU"
+    )
+
+    name = "PythonSlaveWithDebugLogger" if debug_logging else "PythonSlaveWithLogger"
+    category = "category"
+    message = "log message"
+
+    log_calls = [
+        (
+            f"{status.name.upper()} - {debug} - {message}", 
+            status, 
+            category, 
+            debug
+        ) for debug, status in itertools.product([True, False], Fmi2Status)
+    ]
+
+    fmu_calls = "\n".join([
+        '        self.log("{}", Fmi2Status.{}, "{}", {})'.format(c[0], c[1].name, c[2], c[3]) for c in log_calls
+    ])
+
+    slave_code = f"""from pythonfmu.fmi2slave import Fmi2Slave, Fmi2Status, Fmi2Causality, Integer, Real, Boolean, String
+
+
+class {name}(Fmi2Slave):
+
+    def __init__(self, **kwargs):
+        super().__init__(**kwargs)
+
+        self.realIn = 22.0
+        self.realOut = 0.0
+        self.register_variable(Real("realIn", causality=Fmi2Causality.input))
+        self.register_variable(Real("realOut", causality=Fmi2Causality.output))
+
+
+    def do_step(self, current_time, step_size):
+{fmu_calls}
+        return True
+"""
+
+    script_file = tmp_path / "orig" / f"{name.lower()}.py"
+    script_file.parent.mkdir(parents=True, exist_ok=True)
+    script_file.write_text(slave_code)
+
+    fmu = FmuBuilder.build_FMU(script_file, dest=tmp_path)
+
+    fmu = tmp_path / f"{name}.fmu"
+    assert fmu.exists()
+
+    logger = MagicMock()
+
+    fmpy.simulate_fmu(
+        str(fmu),
+        stop_time=1e-3,
+        output_interval=1e-3,
+        logger=logger,
+        debug_logging=debug_logging
+    )
+
+    expected_calls = [
+        call(
+            logger.call_args[0][0],  # Don't test the first argument
+            bytes(name, encoding="utf-8"),
+            int(c[1]),
+            bytes(c[2], encoding="utf-8"),
+            bytes(c[0], encoding="utf-8")
+        ) for c in filter(lambda c: debug_logging or not c[3], log_calls)
+    ]
+    
+    assert logger.call_count == len(Fmi2Status) * (1 + int(debug_logging))
+    logger.assert_has_calls(expected_calls)
diff --git a/pythonfmu/tests/test_variables.py b/pythonfmu/tests/test_variables.py
index bae6281..acb4561 100644
--- a/pythonfmu/tests/test_variables.py
+++ b/pythonfmu/tests/test_variables.py
@@ -7,6 +7,8 @@ from pythonfmu import Fmi2Slave
 from pythonfmu.enums import Fmi2Causality, Fmi2Initial, Fmi2Variability
 from pythonfmu.variables import Boolean, Integer, Real, ScalarVariable, String
 
+from .utils import FMI2PY, PY2FMI
+
 SCALAR_VARIABLE_ATTRIBUTES = ["name", "valueReference", "description", "causality", "variability", "initial"]
 
 def test_ScalarVariable_reference_set_once_only():
@@ -17,9 +19,9 @@ def test_ScalarVariable_reference_set_once_only():
         v.value_reference = 33
 
 
-@pytest.mark.parametrize("causality", list(Fmi2Causality) + [None, ])
-@pytest.mark.parametrize("initial", list(Fmi2Initial) + [None, ])
-@pytest.mark.parametrize("variability", list(Fmi2Variability) + [None, ])
+@pytest.mark.parametrize("causality", list(Fmi2Causality) + [None])
+@pytest.mark.parametrize("initial", list(Fmi2Initial) + [None])
+@pytest.mark.parametrize("variability", list(Fmi2Variability) + [None])
 @pytest.mark.parametrize("name, description", [
     ("var", None),
     ("var", "description of var"),
@@ -35,6 +37,64 @@ def test_ScalarVariable_constructor(causality, initial, variability, name, descr
     assert var.variability == variability
 
 
+@pytest.mark.parametrize("fmi_type,value", [
+    (Boolean, False),
+    (Integer, 22),
+    (Real, 2./3.),
+    (String, "hello_world"),
+])
+def test_ScalarVariable_getter(fmi_type, value):
+
+    class Slave(Fmi2Slave):
+
+        def __init__(self, **kwargs):
+            super().__init__(**kwargs)
+            self.var = [value]
+            self.register_variable(PY2FMI[type(value)]("var", getter=lambda: self.var[0]))
+
+        def do_step(self, t, dt):
+            return True
+
+    py_type = FMI2PY[fmi_type]
+    fmi_type_name = fmi_type.__qualname__.lower()
+
+    slave = Slave(instance_name="slaveInstance")
+    assert getattr(slave, f"get_{fmi_type_name}")([0, ]) == [value, ]
+
+
+@pytest.mark.parametrize("fmi_type,value", [
+    (Boolean, False),
+    (Integer, 22),
+    (Real, 2./3.),
+    (String, "hello_world"),
+])
+def test_ScalarVariable_setter(fmi_type, value):
+
+    class Slave(Fmi2Slave):
+
+        def __init__(self, **kwargs):
+            super().__init__(**kwargs)
+            self.var = [None]
+            self.register_variable(
+                PY2FMI[type(value)](
+                    "var",
+                    getter=lambda: self.var[0],
+                    setter=lambda v: self.var.__setitem__(0, v)
+                )
+            )
+
+        def do_step(self, t, dt):
+            return True
+
+    slave = Slave(instance_name="slaveInstance")
+    py_type = FMI2PY[fmi_type]
+    fmi_type_name = fmi_type.__qualname__.lower()
+
+    set_method = getattr(slave, f"set_{fmi_type_name}")
+    set_method([0, ], [value, ])
+    assert getattr(slave, f"get_{fmi_type_name}")([0, ]) == [value, ]
+
+
 @pytest.mark.parametrize("causality", list(Fmi2Causality) + [None, ])
 @pytest.mark.parametrize("initial", list(Fmi2Initial) + [None, ])
 @pytest.mark.parametrize("variability", list(Fmi2Variability) + [None, ])
@@ -64,9 +124,9 @@ def test_ScalarVariable_to_xml(causality, initial, variability, name, descriptio
     (Integer, 23),
     (Real, 15.),
     (String, "hello")])
-@pytest.mark.parametrize("causality", list(Fmi2Causality) + [None, ])
-@pytest.mark.parametrize("initial", list(Fmi2Initial) + [None, ])
-@pytest.mark.parametrize("variability", list(Fmi2Variability) + [None, ])
+@pytest.mark.parametrize("causality", list(Fmi2Causality) + [None])
+@pytest.mark.parametrize("initial", list(Fmi2Initial) + [None])
+@pytest.mark.parametrize("variability", list(Fmi2Variability) + [None])
 def test_ScalarVariable_start(var_type, value, causality, initial, variability):
     var_obj = var_type("var", causality=causality, description="a variable", initial=initial, variability=variability)
 
diff --git a/pythonfmu/tests/utils.py b/pythonfmu/tests/utils.py
new file mode 100644
index 0000000..2771ac6
--- /dev/null
+++ b/pythonfmu/tests/utils.py
@@ -0,0 +1,9 @@
+from pythonfmu.variables import Boolean, Integer, Real, ScalarVariable, String
+
+FMI2PY = dict((
+    (Boolean, bool),
+    (Integer, int),
+    (Real, float),
+    (String, str)
+))
+PY2FMI = dict([(v, k) for k, v in FMI2PY.items()])