Anton's website

Wrapping C++ with Cython: log forwarding

Back to the yaacrl and pyaacrl! Today we will look at the forwarding of log messages from C++ library to the Python wrapper and a logging module: how to do it and how it works.

All of the code is based on the code from the previous article, but I believe that reading the latter is not required as this article is fairly standalone.

Adding an extendable logging system to yaacrl

Unlike in the Python ecosystem, where we have an awesome logging module, C/C++ world doesn't have a de-facto standard solution to writing logs. Some libraries offer rigid systems that we cannot amend, some offer certain extendability to the message handlers, some offer no logging at all. The first and last options barely give us any way to create any custom solution, but the middle one is what we need.

Libraries with amendable logging solutions only implement functions to produce log messages. Consumption of those messages needs to be created by the end users of the library. Despite certain differences, usually, it is done in two steps:

  • implementing message handler, which could be either class or function
  • injecting defined handler into the target library.

Both steps could be done in a myriad of ways. The simplest one I saw so far is the SQLite3 errorlog (it only logs errors)

// Handler function, that writes error messages to stderr
void errorLogCallback(void *pArg, int iErrCode, const char *zMsg){
    fprintf(stderr, "(%d) %s\n", iErrCode, zMsg);
}

// config function, that sets global handler
sqlite3_config(SQLITE_CONFIG_LOG, errorLogCallback, pData);

Qt Framework has a very similar approach, but as it produces messages of different levels it also passes log level to the handler:

// QtMsgType is enum of DEBUG, INFO, WARNING, ERROR, etc
void myMessageHandler(QtMsgType,
                      const QMessageLogContext &,
                      const QString &) {
    ...
}

// same here - injecting a handler with a function
qInstallMessageHandler(myMessageHandler);

wxWidgets logging system relies on classes but still looks the same. Instead of calling a function, we should inherit a base class and override a few methods:

// override built-in wxLog class
class CustomLogger: wxLog {
  virtual void DoLogRecord (wxLogLevel level,
                            const wxString &msg,
                            const wxLogRecordInfo &info);
}

// instantiate new logger and pass it to the config function
wxLog* logger = new CustomLogger();
wxLog::SetActiveTarget(logger);

All these solutions are very similar, and attaching each of them to Python works in the very same way. In order to showcase it in pyaacrl, I've implemented a Qt-like solution in the original yaacrl library: a simple function that accepts a message and log level.

Here is a Cython definitions of yaacrl logging interfaces:

# pyaacrl/cython_src/lib.pxd

cdef extern from "yaacrl/config.h" namespace "yaacrl":
    # enum class from C++11 is used for log levels
    cdef enum CppLogLevel "yaacrl::LogLevel":
        Cpp_DEBUG "yaacrl::LogLevel::DEBUG"
        Cpp_INFO "yaacrl::LogLevel::INFO"
        Cpp_WARNING "yaacrl::LogLevel::WARNING"
        Cpp_ERROR "yaacrl::LogLevel::ERROR"

    # Function to set global logger
    cdef void set_logger(void(*)(CppLogLevel, string))

Or you can check out C++ header and implementation files (spoiler: nothing interesting there).

Forwarding from custom handler to logging

This is where Cython magic kicks in. Without hesitations, here is a complete solution:

# type extensions from previous article here
...
import logging

# Get module logger
logger = logging.getLogger('pyaacrl')

# Custom handler function
cdef void _custom_logger(CppLogLevel cpp_level, string log_msg):
    if   cpp_level == Cpp_DEBUG:   logger.debug(log_msg)
    elif cpp_level == Cpp_INFO:    logger.info(log_msg)
    elif cpp_level == Cpp_WARNING: logger.warning(log_msg)
    elif cpp_level == Cpp_ERROR:   logger.error(log_msg)

set_logger(_custom_logger)  # imported from lib.pxd

How cool is that?

Creating and using logger is in no way different from your typical Python code. The more interesting detail is that we just called a C++ function at the top level of the file. That's not something we can do in pure C/C++.

Let's take a look at the generated code to see how it works. I made a lot of simplifications (e.g., changed naming, simplified some Python/C API calls, removed refcounting) to make it more readable, but the general concepts are untouched.

First of all, take a look at the module initialization flow:

// Slots are the functions to execute during module import
static PyModuleDef_Slot moduledef_slots[] = {
    {1, (void*)pymod_create},
    {2, (void*)pymod_exec_pyaacrl_cy},
    {0, NULL}
};

// structure that describes a module
static struct PyModuleDef moduledef = {
    ...
    moduledef_slots,  // connect the slots to the module
    ...
};

// module namespace object, global variable
static PyObject *d;



// slot function, which is of interest to us
static int pymod_exec_pyaacrl_cy(PyObject *pyinit_module) {
    ...

    // create a module namespace (which is just a <dict>)
    d = PyModule_GetDict(pyinit_module);

    // import logging and get getLogger attribute
    PyObject *t_1 = Pyx_Import(n_s_logging, 0, -1);
    PyObject *t_2 = PyObject_GetAttrString(t_1, "getLogger");

    // prepare call args for getLogger() call and perform the call
    PyObject *tuple__5 = PyTuple_Pack(1, PyUnicode_DecodeUTF8("pyaacrl", 7)); 
    t_1 = PyObject_Call(t_2, tuple__5, NULL);

    // Save call result to the module namespace
    PyDict_SetItemString(d, "logger", t_1);

    // Just a normal C++ function call, bind handler to yaacrl logging
    yaacrl::set_logger(pyaacrl_cy__custom_logger);
    ...
}

All the file's top-level code is executed right during the module import, including the creation of logger and yaacrl::set_logger call. Also, during this step module creates its own namespace, which is used to store module variables, such as logger.

Depending on the Python version, a different way of executing code during the import is used. In given example (Python 3.5+ ) PEP-489 (Multi-phase extensions initialization) is used, otherwise everything goes into PyInit_pyaacrl_cy function.

Now, take a look at the code of the generated custom handler:

static void pyaacrl_cy__custom_logger(
    enum yaacrl::LogLevel cpp_level,
    std::string log_msg
) {
    ...
    switch (cpp_level) {
        case yaacrl::LogLevel::DEBUG:
            ...
            // get logger object from the module namespace
            PyObject* t_2 = PyDict_GetItemString(d, "logger");
    
            // convert std::string to Python <str>, and create call args tuple
            t_3 = PyUnicode_DecodeUTF8(log_msg.data(), log_msg.size(), NULL);
            PyObject* tuple__3 = PyTuple_Pack(1, t_3);
    
            // call logger.debug with a converted string
            PyObject* t_4 = PyObject_GetAttrString(t_2, "debug");
            PyObject_Call(t_4, tuple__3, NULL);
      
            break;
        case yaacrl::LogLevel::INFO:
            ...

        // other case-branches look the same, but call other methods 
        // e.g., logger.info() for yaacrl::LogLevel::INFO
    }
    ...
}

This is very similar to how a usual Python program works: find a variable in scope by name and then do whatever you want with it. We rely on the fact that the module namespace is a global variable and initialized during import. That means that we are sure that logger variable is there and ready to be used.

Update on error handling in Cython

CPython relies on function return values to process exceptions in runtime. cdef functions that return C types can't propagate exceptions in the same way, so custom error handling must be applied. Cython has a specific chapter in docs on this matter.

However, docs don't help in our case because custom_logger returns nothing at all (void). Thus, errors that occur inside of it are lost and not handled by the caller. For instance, Ctrl-C will not stop the program because KeyboardInterrupt is dismissed.

The simplest workaround is to make sure all errors are handled inside of such function, and I consider it okayish for my particular case:

cdef void _custom_logger(CppLogLevel cpp_level, string log_msg):
    try:
        ...
    except KeyboardInterrupt:
        exit(1)

However, I encourage you to pay extra attention to error handling in your cdef functions . Also, cysignals library is worth looking at if you rely on signals in your application.

Happy ending

So now we have awesome pythonic logging in pyaacrl, which forwards all the message of the parent library. We can also mix our own messages using the logger variable inside of the extension types' methods. But most importantly - library consumers can now use the whole power of logging module: add handlers, change levels, and so on.

Despite being very small, I think this example is a great demo of Cython capabilities. It is extremely easy to even forgot that you are writing some C++-based code, and integrating it with Python is literally seamless.

As usual, you can find the code on the GitHub: https://github.com/azhpushkin/pyaacrl