Wrapping of logger calls

[honkomonk]

While I see the convenience in wrapping Python's logging facilities, I would recommend to not wrap everything. Wrapping the actual logging calls, masks the origin of the messages. We use verbose logging messages for development with file, function, lineno information (see: https://docs.python.org/3/library/logging.html#logrecord-attributes), but messages from the Vimba module are displayed as originating from the wrapping functions. Debbuging a 12:31:30,575 | log.py:234 | Error | <VmbError.BadParameter: -7> message would be easier, if I can see directly where in the code it's from. My recommendation: Keep the whole logging configuration mechanism as it is, but use direct calls to the Python logger throughout the code.

Also: You redefined the logger's "debug" level as "trace". If you want something more verbose as "debug" you could define a new level and keep the default ones untouched: https://stackoverflow.com/questions/47888855/python3-add-logging-level

Having said that ... I really like the new VimbaPython bindings. Makes prototyping and working with the Vimba drivers a lot easier. :-)

[NiklasKroeger-AlliedVision]

Thank you for the feedback! I agree, that having all error messages emerge from log.py does not really make it easier to figure out where the actual message was generated. To be honest I am not currently sure why a custom wrapper class was chosen during implementation of VimbaPython. Possibly the reason was the requirement for the trace level and the log level setting (e.g. Vimba.get_instance().enable_log(LOG_CONFIG_INFO_CONSOLE_ONLY)) to keep similarity with our other Vimba APIs as high as possible.

I will definitely take a closer look at this and see if we can get around the requirement of a custom class to make better use of the python logging module. However this will take some time to result in actual changes in validated and released versions of VimbaPython.

[NiklasKroeger-AlliedVision]

Okay I have played around with the logger a little bit and I found a way to hack support for correct line numbers into it. Please take this as an unvalidated and hacky workaround that should work but might be very fragile and has only been tested very quickly.

diff --git a/vimba/util/log.py b/vimba/util/log.py
index 21d3500..709e779 100644
--- a/vimba/util/log.py
+++ b/vimba/util/log.py
@@ -260,7 +260,15 @@ class Log:
     @staticmethod
     def get_instance() -> '__Impl':
         """Get Log instance."""
-        return Log.__instance
+        # DIRTY HACK TO GET CORRECT SOURCE LINES FROM LOGGING OUTPUT
+        tmp = logging.getLogger("VimbaPythonLog")
+        # VimbaPython uses a trace level. Map to debug for now
+        tmp.trace = tmp.debug
+        # Enabling of log levels is now done via logging configuration -> .enable becomes useless
+        # Method still needed because parts of VimbaPython call it -> make it a noop
+        tmp.enable = lambda x: None
+        return tmp
+        # return Log.__instance

 def _build_cfg(console_level: Optional[LogLevel], file_level: Optional[LogLevel]) -> LogConfig:

In my tests this seemed to output nicer line numbers and filenames. Running any of our examples (I just used list_cameras.py) with the following change gives nice and seemingly correct line numbers in your format:

diff --git a/Examples/list_cameras.py b/Examples/list_cameras.py
index 1168001..63b65b7 100644
--- a/Examples/list_cameras.py
+++ b/Examples/list_cameras.py
@@ -54,4 +54,6 @@ def main():

 if __name__ == '__main__':
+    import logging
+    logging.basicConfig(format='%(asctime)s | %(filename)s:%(lineno)d | %(funcName)s | %(message)s', level=logging.INFO)
     main()

Resulting logging line from this change:

2021-03-18 16:44:39,329 | vimba.py:480 | _startup | Starting VimbaPython: 1.1.0 (using VimbaC: 1.8.4, VimbaImageTransform: 1.6)

which is exactly the line the logging.info() call is made.

Just to say it again. This is a workaround but I agree, that this logging output is far more helpful for actual debugging than the current output where every log statement originates from log.py. I will see when and how we can integrate something similar into an official release of VimbaPython, but this will take some time.

[honkomonk]

Yes, that should do it. Thanks for the quick response.

It would just be a nice improvement in the future. So, no need for urgency.