Support for registerLogHandler() in Python interface

[davehawthorne]

The Python API's otherwise excellent coverage of the C API feature set is missing support for registerLogHandler(). Which means that one's Python code can't intercept and handle log messages (without nasty measures such as redirecting stderr). The upshot is that Python code remains in the dark when some errors and warnings (such as failed calibrations) are flagged.

Granted, supporting Python callbacks is a bit of a pain as the log messages can come from multiple threads - which breaks the GIL. Here at DEK we've been playing around with a solution to this that seems to work. It relies on a thread-safe queue that can be checked as the end of each API call. So far the change is confined to some hacking in python/SoapyAPI.i https://github.com/DEK-Technologies/SoapySDR/tree/python_logging

[davehawthorne]

The current solution doesn't support the raising of exceptions from the log function which makes error handling a bit ugly. An example usage follows:

"""Example code to demonstration registerLogHandler()

This is an attempt to provide the same log interception
functionality as provided by the C API.
"""
import sys
import SoapySDR

# A crude record of warning and error messages as reported by SoapySDR::log().
error_log = []

def my_log_handler(log_level, log_message):
    """Example callback to handle SoapySDR log messages.

    Displays all messages to stderr.
    Records Warnings and worse in a global list so that
    our Python code can be made aware of an otherwise hidden
    fault.
    """
    print("Log Level {}: '{}'".format(log_level, log_message), file=sys.stderr)
    if log_level <= SoapySDR.SOAPY_SDR_WARNING:
        error_log.append((log_level, log_message))

def have_fault():
    """Has there been a warning or worse flagged?

    (Since clear_faults() was last called.)
    """
    return len(error_log) > 0

def clear_faults():
    """Empty the error log."""
    error_log.clear()

def main():
    SoapySDR.registerLogHandler(my_log_handler)
    try:
        device = SoapySDR.Device()
    except RuntimeError:
        print("Aborting! RuntimeError.")
        return
    if have_fault():
        print("Aborting! problems reported.")
        return
    UNSUPPORTED_FREQ_HZ = 1000
    device.setSampleRate(SoapySDR.SOAPY_SDR_RX, 0, UNSUPPORTED_FREQ_HZ)
    if have_fault():
        print("Aborting! problems reported.")
        return
    print("All good.")

if __name__ == '__main__':
    main()

[guruofquality]

Its a good suggestion. In terms of implementation, swig directors is the way to go here. That should take care of the thread locking and gil stuff.

The swig directors basically let you overload a C++ class with a virtual function in python. So in this case, some python object with an overloaded log handler gets called.

Thats not a big deal, but there is a bit of thought into making it fit with python logging API. We can wrap things up to have an identical looking API, or maybe it should be more pythonic to fit in with python's logging framework.

[guruofquality]

@davehawthorne can you try this branch: https://github.com/pothosware/SoapySDR/tree/python_logging - It implements SoapySDR.registerLogHandler()

Example:

def myLogHandler(lvl, msg):
    print('Got a log: %d, %s'%(lvl, msg))

SoapySDR.registerLogHandler(myLogHandler)
SoapySDR.SoapySDR_log(SOAPY_SDR_INFO, "HELLO")

PS

I did a little experimenting with making it by default forward to a logger from python. -- The pythonic way would be to call getLogger() and to register a custom handler. But the logging by default does not look very nice compared to the default handler as it is now. So I might have to make that another function to install the pythonic logger: like SoapySDR.setupLogging() which would do this more or less

    def handle(self, lvl, msg):
        self.logger = logging.getLogger('SoapySDR')
        if lvl == SOAPY_SDR_FATAL: return self.logger.critical(msg)
        if lvl == SOAPY_SDR_CRITICAL: return self.logger.critical(msg)
        if lvl == SOAPY_SDR_ERROR: return self.logger.error(msg)
        if lvl == SOAPY_SDR_WARNING: return self.logger.error(msg)
        if lvl == SOAPY_SDR_NOTICE: return self.logger.info(msg)
        if lvl == SOAPY_SDR_INFO: return self.logger.info(msg)
        if lvl == SOAPY_SDR_DEBUG: return self.logger.debug(msg)
        if lvl == SOAPY_SDR_TRACE: return self.logger.debug(msg)
        if lvl == SOAPY_SDR_SSI:
            sys.stderr.write(msg)
            sys.stderr.flush()

[davehawthorne]

Nice. Using directors is a much cleaner approach than what I proposed.

I've been doing some testing of your branch on my LimeSDR USB setup. These are some of my observations to date:

• Exceptions thrown in the log handler aren't propagated through the C++ back to Python. I think this is fixed on the DEK fork https://github.com/DEK-Technologies/SoapySDR/tree/pot_py_logging

• I've had an intermittent issue where messages stop getting logged and only a restart of Python will fix it. This seems to happen after an "alarm storm" such as the stream of "Write(64 bytes) failed" errors reported on a Lime SDR USB getting unplugged. I'll do some more characterization and report back to you.

• The passing of an invalid callback to SoapySDR.registerLogHandler() is accepted without complaint, however it halts all logging. Subsequently specifying a valid callback doesn't fix things. Only by resetting the handler to the default do we get logging back - see below.

On a whim, I tossed in the means of restoring the system back to use the default handler by calling SoapySDR.registerLogHandler(None). Note that this requires a small change to the C code and a small addition to the C API (Calling SoapySDR_registerLogHandler(nullptr) sets registeredLogHandler back to defaultLogHandler(). I accept this might not have merit beyond my test needs.

[guruofquality]

Cool, can you make a pull request with your "pot_py_logging" branch to merge into "maint"?

Exceptions thrown in the log handler aren't propagated through the C++ back to Python. I think this is fixed on the DEK fork https://github.com/DEK-Technologies/SoapySDR/tree/pot_py_logging

I suppose if the custom log handler can throw, then the SoapySDR_pythonLogHandler should try/except it to be safe. Seems like good boiler plate to add regardless.

I did notice:

• catch (Swig::DirectorException &e) { SWIG_fail; } should be const
• throw Swig::DirectorMethodException("DAVE"); Lol whats DAVE

Also, on a whim, I tossed in the means of restoring the system back to use the default handler by calling SoapySDR.registerLogHandler(None). Note that this requires a small change to the C code and a small addition to the C API (Calling SoapySDR_registerLogHandler(nullptr) sets registeredLogHandler back to defaultLogHandler(). I accept this might not have merit beyond my test needs.

Seems like a good idea actually

[davehawthorne]

The couple of issues you raised have been fixed (oops). I've also updated the comments in the logger include files (and checked they flow through to the Doxygen output).

Note that I've breached the GitHub commit guidelines by appending periods to the commit summaries. Sorry.

[guruofquality]

Looks great, I like the cleanup and restore of the logger.

[davehawthorne]

A minor typo in the changes to SoapySDR.i has exposed SoapySDR.logf() to the API. This is fixed in a commit that also added a module level docstring (admittedly exceeding the remit of this issue). The text is largely lifted from the pothosware web site. You'll want to modify this I suspect.

The commits are on the DEK py_pot_logging branch. Let me know if you want me to do a second pull request.

It struck me that including some of the documentation from the h/hpp files in Python docstrings would be rather handy. SWIG's development build (4.0) supports automatic translation of Doxygen commenting to docstrings, however the release version (3.0) doesn't.

[guruofquality]

sure do another PR