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:
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()])