Support logging

[markaren]

self.log("") will always print
self.log("", debug=True) will print if FMI debugLogging is set

Closes #35
Closes #85

[fcollonval]

@markaren I try slightly different technique to pass a Python object rather than the pointer to the logger function (this is a bit weird to pass an address to Python). But without success.

So I build on top of your PR to add tests of the feature. They brought strange results. If I don't set debug_logging to True in the simulate_fmu call, no log message is passed to the FMU caller. And if I do, it works. But the argument debug of the log method becomes useless.

The other point is the test errors. If I run all tests with all possible values for the message status, only the first status used is correct. To put it differently, if I execute the new tests separately they all pass. But running them all together makes them failed except for the two first one.

Any idea how to fix the tests? And what is the correct behavior for turning on or off the log messages?

[markaren]

Status seems to always have the value 0 when parameterized.. Even when doing

@pytest.mark.parametrize("status", [Fmi2Status.ok, Fmi2Status.warning])

Also, Fmi2Status must be imported

[markaren]

At least what we have now is better than what we had. But I have no idea why the tests failed with the previous test setup. Also I wonder if this logging mechanism will pose problems when multiple FMUs are loaded in the same process.

[markaren]

Also I wonder if this logging mechanism will pose problems when multiple FMUs are loaded in the same process.

Perhaps that's why it failed. It may throw an exception on the second LoadLibrary call that we do not see the output from..

[markaren]

Indeed. LoadLibrary throws an exception. No idea how to handle that. Ignore logging from additional FMUs loaded in the same process?

[fcollonval]

@markaren thanks for looking into this.

This is particularly annoying and brought back the need to better isolate multiple Python FMUs.

[markaren]

This is particularly annoying and brought back the need to better isolate multiple Python FMUs.

I'm not sure that will help tbh. Loading shared libraries should be system wide no?

Footnote: I have the same issue in Java, where I'm not even able to load the library once, as we seem to be able to do here.

[fcollonval]

Can you report here the exception message you are seeing (I'm unable to get it)?

Ignore logging in from additional FMUs loaded in the same process?

This sounds like a dirty hack. But if it is simple to set up, that could be a temporary solution.

[markaren]

I don't know what Exception to catch so I don't have any exception output.

[fcollonval]

I don't know what Exception to catch so I don't have any exception output.

Thanks for the reply. This is definitely complicated to debug.

Loading shared libraries should be system wide no?

No idea

Footnote: I have the same issue in Java, where I'm not even able to load the library once, as we seem to be able to do here.

That is the reason I think it would be better to pass directly a callback function. Unfortunately, what I have seen for Python required to define a new Python Object type. But this is complicated by the usage of the limited API.
I'll try to push a branch so you could have a look.

[fcollonval]

Looking at a357a84, I forgot but you can catch the exception and print it with:

                try:
                    self.__lib = cdll.LoadLibrary(str(library_path))
                except Exception as e:
                    print(e)

[markaren]

That is the reason I think it would be better to pass directly a callback function.

That's definitely possible for the Java version. I've done something similar before for JNI. Perhaps it's the solution here as well as you say.

[fcollonval]

I tested successfully the following on Linux. The change is to use a different name for the slave class for each test (and therefore for the library).

So this confirms the problem when loading twice a library with the same name and API...

Could you try it on Windows?

@pytest.mark.integration
@pytest.mark.parametrize("debug", [True, False])
@pytest.mark.parametrize("status", Fmi2Status)
def test_logger(tmp_path, debug, status):
    fmpy = pytest.importorskip(
        "fmpy", reason="fmpy is not available for testing the produced FMU"
    )

    name = f"PythonSlaveWithLogger{status.name}{debug}"
    category = "category"
    message = "log message"

    slave_code = f"""from pythonfmu.fmi2slave import Fmi2Slave, 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):
        self.log("{message}", {status}, "{category}", {debug})
        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=True
    )

    logger.assert_called_once_with(
        logger.call_args[0][0],  # Don't test the first argument
        bytes(name, encoding="utf-8"),
        int(status),
        bytes(category, encoding="utf-8"),
        bytes(message, encoding="utf-8")
    )

[markaren]

Works :)

[fcollonval]

So the remaining questions:

• What is the best test for this feature?
  I would say the last version testing all flags within the same FMU is closer to the user usage.

• Where to put a big warning on loading FMU with the same name?

I understand now some errors I saw on tests with our code using PythonFMU as FMPy is also using LoadLibrary to use a FMU.

• Should we specify canBeInstantiatedOnlyOncePerProcess = true?

• Should we keep the debug argument as it does not make any difference (at least when using FMPy)?
  I can not figure out if this is a bug with FMPy (i.e. debug_logging=True is required to print any log message) or with our code.

[markaren]

I can not figure out if this is a bug with FMPy (i.e. debug_logging=True is required to print any log message) or with our code.

self.log("Hello World!") will print in FMPy when debug_logging=False.

Should we specify canBeInstantiatedOnlyOncePerProcess = true

I rather not as that will make some tools fail importing it. Better to just turn of logging in this case.

Where to put a big warning on loading FMU with the same name?

I think it is ok as is. A warning is printed saying logging will not work for this particular instance.

[fcollonval]

self.log("Hello World!") will print in FMPy when debug_logging=False.

Oh thanks for the info. At one point I had a different behavior. So indeed debug is working as expected. I'll push a commit to test the behavior.

[fcollonval]

Thanks @markaren for the discussion. It is good to go for me.