Trying to get logging messages from C++ to Python. Not working currently because the pointer to the file descriptor is not the same across modules.

Author: NikoOinonen

ppafm/GridUtils.py

@@ -5,7 +5,7 @@
 import numpy as np
 
 from . import cpp_utils
-from .logging_utils import get_logger
+from .logging_utils import CppLogger, get_logger
 
 logger = get_logger("GridUtils")
 
@@ -160,5 +160,6 @@ def sphericalHist(data, center, dr, n):
 
 def readNumsUpTo(filename, dimensions, noline):
     N_arry = np.zeros((dimensions[0] * dimensions[1] * dimensions[2]), dtype=np.double)
-    lib.ReadNumsUpTo_C(filename.encode(), N_arry, dimensions, noline)
+    with CppLogger("GridUtils"):
+        lib.ReadNumsUpTo_C(filename.encode(), N_arry, dimensions, noline)
     return N_arry

ppafm/__init__.py

@@ -1,6 +1,7 @@
 #!/usr/bin/python
 
-# Importing the logging utils sets up the default root logger
-from . import logging_utils
 from .common import *
+from .logging_utils import _init_logging
 from .version import __version__
+
+_init_logging()

ppafm/cpp/GridUtils.cpp

@@ -3,6 +3,7 @@
 //#include <string.h>
 
 #include "Grid.h"
+#include "logging.h"
 
 #include <locale.h>
 
@@ -42,8 +43,8 @@ extern "C" {
         int nx=dims[0];
         int ny=dims[1];
         int nz=dims[2];
-        printf ("FileRead program: reading %s file\n", fname);
-        printf ("XYZ dimensions are %d %d %d\n", dims[0], dims[1], dims[2]);
+        log_info ("FileRead program: reading %s file\n", fname);
+        log_info ("XYZ dimensions are %d %d %d\n", dims[0], dims[1], dims[2]);
         f=fopen(fname, "r");
         if (f==NULL)        {
             fprintf(stderr, "Can't open the file %s", fname);

ppafm/cpp/Makefile

@@ -9,7 +9,7 @@ CPPFLAGS= -fPIC -std=c++11 -O2 -mtune=native -fopenmp
 LDFLAGS= -shared -fopenmp
 
 
-all: PP GU fitting_ fitSpline_
+all: PP GU fitting_ fitSpline_ logging_
 
 PP: ProbeParticle.o
 
@@ -19,6 +19,8 @@ fitting_: fitting.o
 
 fitSpline_: fitSpline.o
 
+logging_: logging.o
+
 # .o files depend on .cpp files with same prefix
 # $@ target, $< prerequisite, $* matched stencil
 %.o:: %.cpp

ppafm/cpp/logging

@@ -0,0 +1,15 @@
+
+#include "logging.h"
+
+extern "C"{
+
+    void set_log_fd(int fd) {
+        set_log_fd_(fd);
+    }
+
+    void test_log() {
+        log_info("test message 1");
+        // log_debug("test message 2\nanother line");
+    }
+
+}

ppafm/cpp/logging.cpp

@@ -0,0 +1,33 @@
+
+#ifndef logging_h
+#define logging_h
+
+#include <stdio.h>
+#include <stdarg.h>
+
+#include <string>
+
+int log_fd = 1;
+
+void log(const char* log_level, const char* format, ...) {
+    std::string log_level_str = "LOG_ENTRY_" + std::string(log_level) + std::string(" ");
+    std::string format_str = log_level_str + std::string(format);
+    va_list arg_list;
+    va_start(arg_list, format);
+    printf("log_fd %d %p\n", log_fd, &log_fd);
+    vdprintf(log_fd, format_str.c_str(), arg_list);
+}
+
+void log_info(const char* format, ...) {
+    va_list arg_list;
+    va_start(arg_list, format);
+    log("INFO", format, arg_list);
+}
+
+void set_log_fd_(int fd) {
+    printf("Setting fd %d %d %p\n", log_fd, fd, &log_fd);
+    log_fd = fd;
+    printf("Setting fd %d %d %p\n", log_fd, fd, &log_fd);
+}
+
+#endif

ppafm/cpp/logging.h

@@ -29,7 +29,7 @@
 logger.debug(f" PACKAGE_PATH = {PACKAGE_PATH}")
 logger.debug(f" CPP_PATH     = {CPP_PATH}")
 
-cpp_modules = {"PP": "ProbeParticle", "GU": "GridUtils", "fitting": "fitting", "fitSpline": "fitSpline"}
+cpp_modules = {"PP": "ProbeParticle", "GU": "GridUtils", "fitting": "fitting", "fitSpline": "fitSpline", "logging": "logging"}
 """Dictionary of C++ extension modules. Keys are targets for make and values are module names."""
 
 

ppafm/cpp_utils.py

@@ -1,6 +1,7 @@
 import logging
 import os
 import sys
+import tempfile
 from typing import Any, Optional, Union
 
 # Setup the root logger for the ppafm package. All other loggers will be derived from this one.
@@ -15,6 +16,8 @@
 _perf_log_format = "[%(asctime)s - %(name)s] %(message)s"
 _perf_log_enabled = False
 
+lib = None
+
 
 def configure_logging(
     level: Optional[Union[int, str]] = None,
@@ -45,7 +48,7 @@ def configure_logging(
 
     if level is None:
         try:
-            level = os.environ["PPAFM_LOG_LEVEL"]
+            level = os.environ["PPAFM_LOG_LEVEL"].upper()
         except KeyError:
             level = logging.INFO
     _root_logger.setLevel(level)
@@ -95,9 +98,64 @@ def configure_logging(
     _log_handler.setFormatter(logging.Formatter(fmt=_log_format))
 
 
-# This sets the logging level immediately from environment variable or defaults to INFO.
-# Also sets the message format.
-configure_logging()
+def _init_logging():
+
+    global lib
+    if lib is not None:
+        return
+
+    configure_logging()
+
+    # We have to do this import here, or otherwise we get a circular import
+    from .cpp_utils import get_cdll
+
+    lib = get_cdll("logging")
+    lib.set_log_fd(sys.stdout.fileno())
+
+    with CppLogger("test_logger"):
+        lib.test_log()
+
+
+def _get_lib():
+    if lib is None:
+        raise RuntimeError("Logging not initialized")
+    return lib
+
+
+class CppLogger:
+    """Context manager for redirecting logging events in C++ to Python logging."""
+
+    def __init__(self, logger_name: str):
+        self.logger = get_logger(logger_name)
+        self.lib = _get_lib()
+
+    def __enter__(self):
+        self.log = tempfile.TemporaryFile()
+        self.lib.set_log_fd(self.log.fileno())
+
+    def __exit__(self, exc_type, exc_value, exc_traceback):
+        self.log.seek(0)
+
+        # Read file line-by-line and convert messages to logging events
+        log_level = logging.INFO
+        msg = ""
+        for line in self.log:
+            line = line.decode().strip()
+            if line.startswith("LOG_ENTRY_"):
+                if msg:
+                    self.logger.log(log_level, msg)
+                    msg = ""
+                line = line.removeprefix("LOG_ENTRY_")
+                level_str, msg = line.split(" ", maxsplit=1)
+                log_level = getattr(logging, level_str)
+            else:
+                msg += f"\n{line}"
+        if msg:
+            self.logger.log(log_level, msg)
+
+        self.log.close()
+
+        self.lib.set_log_fd(sys.stdout.fileno())
 
 
 def get_logger(name: str) -> logging.Logger: