pyhelper: Add ability to route error messages to python logging

Instead of writing error messages to stderr, route them into the
python code and use the standard python logging system.

Signed-off-by: Kevin O'Connor <kevin@koconnor.net>

docs/Installation.md

@@ -129,7 +129,7 @@ The host software is executed by running the following as the regular
 "pi" user:
 
 ```
-~/klippy-env/bin/python ~/klipper/klippy/klippy.py ~/printer.cfg -l /tmp/klippy.log < /dev/null > /tmp/klippy-errors.log 2>&1 &
+~/klippy-env/bin/python ~/klipper/klippy/klippy.py ~/printer.cfg -l /tmp/klippy.log < /dev/null > /dev/null 2>&1 &
 ```
 
 Once Klippy is running, use a web-browser and navigate to the

docs/Todo.md

@@ -51,8 +51,6 @@ Host user interaction
 
 * Improve logging:
 
- * Route errors from the host C code to the main log file.
-
  * Automatically roll Klippy log files. The default log file should
    have the current date in the log file name.
 

klippy/chelper.py

@@ -71,6 +71,10 @@ defs_serialqueue = """
         , struct pull_queue_message *q, int max);
 """
 
+defs_pyhelper = """
+    void set_python_logging_callback(void (*func)(const char *));
+"""
+
 # Return the list of file modification times
 def get_mtimes(srcdir, filelist):
     out = []
@@ -95,15 +99,23 @@ def check_build_code(srcdir):
 
 FFI_main = None
 FFI_lib = None
+pyhelper_logging_callback = None
 
 # Return the Foreign Function Interface api to the caller
 def get_ffi():
-    global FFI_main, FFI_lib
+    global FFI_main, FFI_lib, pyhelper_logging_callback
     if FFI_lib is None:
         srcdir = os.path.dirname(os.path.realpath(__file__))
         check_build_code(srcdir)
         FFI_main = cffi.FFI()
         FFI_main.cdef(defs_stepcompress)
         FFI_main.cdef(defs_serialqueue)
+        FFI_main.cdef(defs_pyhelper)
         FFI_lib = FFI_main.dlopen(os.path.join(srcdir, DEST_LIB))
+        # Setup error logging
+        def logging_callback(msg):
+            logging.error(FFI_main.string(msg))
+        pyhelper_logging_callback = FFI_main.callback(
+            "void(const char *)", logging_callback)
+        FFI_lib.set_python_logging_callback(pyhelper_logging_callback)
     return FFI_main, FFI_lib

klippy/pyhelper.c

@@ -5,6 +5,7 @@
 // This file may be distributed under the terms of the GNU GPLv3 license.
 
 #include <errno.h> // errno
+#include <stdarg.h> // va_start
 #include <stdint.h> // uint8_t
 #include <stdio.h> // fprintf
 #include <string.h> // strerror
@@ -29,12 +30,39 @@ fill_time(double time)
     return (struct timespec) {t, (time - t)*1000000000. };
 }
 
+static void
+default_logger(const char *msg)
+{
+    fprintf(stderr, "%s\n", msg);
+}
+
+static void (*python_logging_callback)(const char *msg) = default_logger;
+
+void
+set_python_logging_callback(void (*func)(const char *))
+{
+    python_logging_callback = func;
+}
+
+// Log an error message
+void
+errorf(const char *fmt, ...)
+{
+    char buf[512];
+    va_list args;
+    va_start(args, fmt);
+    vsnprintf(buf, sizeof(buf), fmt, args);
+    va_end(args);
+    buf[sizeof(buf)-1] = '\0';
+    python_logging_callback(buf);
+}
+
 // Report 'errno' in a message written to stderr
 void
 report_errno(char *where, int rc)
 {
     int e = errno;
-    fprintf(stderr, "Got error %d in %s: (%d)%s\n", rc, where, e, strerror(e));
+    errorf("Got error %d in %s: (%d)%s", rc, where, e, strerror(e));
 }
 
 // Return a hex character for a given number

klippy/pyhelper.h

@@ -3,6 +3,8 @@
 
 double get_time(void);
 struct timespec fill_time(double time);
+void set_python_logging_callback(void (*func)(const char *));
+void errorf(const char *fmt, ...) __attribute__ ((format (printf, 1, 2)));
 void report_errno(char *where, int rc);
 char *dump_string(char *outbuf, int outbuf_size, char *inbuf, int inbuf_size);
 

klippy/serialqueue.c

@@ -300,7 +300,7 @@ message_alloc_and_encode(uint32_t *data, int len)
     return qm;
 
 fail:
-    fprintf(stderr, "Encode error\n");
+    errorf("Encode error");
     qm->len = 0;
     return qm;
 }
@@ -856,7 +856,7 @@ serialqueue_free_commandqueue(struct command_queue *cq)
     if (!cq)
         return;
     if (!list_empty(&cq->ready_queue) || !list_empty(&cq->stalled_queue)) {
-        fprintf(stderr, "Memory leak! Can't free non-empty commandqueue\n");
+        errorf("Memory leak! Can't free non-empty commandqueue");
         return;
     }
     free(cq);

klippy/stepcompress.c

@@ -17,9 +17,9 @@
 #include <math.h> // sqrt
 #include <stddef.h> // offsetof
 #include <stdint.h> // uint32_t
-#include <stdio.h> // fprintf
 #include <stdlib.h> // malloc
 #include <string.h> // memset
+#include "pyhelper.h" // errorf
 #include "serialqueue.h" // struct queue_message
 
 #define CHECK_LINES 1
@@ -219,16 +219,16 @@ check_line(struct stepcompress *sc, struct step_move move)
     if (move.count == 1) {
         if (move.interval != (uint32_t)(*sc->queue_pos - sc->last_step_clock)
             || *sc->queue_pos < sc->last_step_clock) {
-            fprintf(stderr, "ERROR: Count 1 point out of range: %d %d %d\n"
+            errorf("Count 1 point out of range: %d %d %d"
-                    , move.interval, move.count, move.add);
+                   , move.interval, move.count, move.add);
             sc->errors++;
         }
         return;
     }
     int err = 0;
     if (!move.count || !move.interval || move.interval >= 0x80000000) {
-        fprintf(stderr, "ERROR: Point out of range: %d %d %d\n"
+        errorf("Point out of range: %d %d %d"
-                , move.interval, move.count, move.add);
+               , move.interval, move.count, move.add);
         err++;
     }
     uint32_t interval = move.interval, p = 0;
@@ -237,13 +237,13 @@ check_line(struct stepcompress *sc, struct step_move move)
         struct points point = minmax_point(sc, sc->queue_pos + i);
         p += interval;
         if (p < point.minp || p > point.maxp) {
-            fprintf(stderr, "ERROR: Point %d of %d: %d not in %d:%d\n"
+            errorf("Point %d of %d: %d not in %d:%d"
-                    , i+1, move.count, p, point.minp, point.maxp);
+                   , i+1, move.count, p, point.minp, point.maxp);
             err++;
         }
         if (interval >= 0x80000000) {
-            fprintf(stderr, "ERROR: Point %d of %d: interval overflow %d\n"
+            errorf("Point %d of %d: interval overflow %d"
-                    , i+1, move.count, interval);
+                   , i+1, move.count, interval);
             err++;
         }
         interval += move.add;
@@ -385,8 +385,8 @@ stepcompress_push_factor(struct stepcompress *sc
     int count = steps + .5 - step_offset;
     if (count <= 0 || count > 1000000) {
         if (count && steps)
-            fprintf(stderr, "ERROR: push_factor invalid count %d %f %f %f %f\n"
+            errorf("push_factor invalid count %d %f %f %f %f"
-                    , sc->oid, steps, step_offset, clock_offset, factor);
+                   , sc->oid, steps, step_offset, clock_offset, factor);
         return 0;
     }
     check_expand(sc, sdir, count);
@@ -419,9 +419,9 @@ stepcompress_push_sqrt(struct stepcompress *sc, double steps, double step_offset
     int count = steps + .5 - step_offset;
     if (count <= 0 || count > 1000000) {
         if (count && steps)
-            fprintf(stderr, "ERROR: push_sqrt invalid count %d %f %f %f %f %f\n"
+            errorf("push_sqrt invalid count %d %f %f %f %f %f"
-                    , sc->oid, steps, step_offset, clock_offset, sqrt_offset
+                   , sc->oid, steps, step_offset, clock_offset, sqrt_offset
-                    , factor);
+                   , factor);
         return 0;
     }
     check_expand(sc, sdir, count);
@@ -452,10 +452,9 @@ stepcompress_push_delta_const(
                  - height - zdist) / step_dist + .5;
     if (count <= 0 || count > 1000000) {
         if (count)
-            fprintf(stderr, "ERROR: push_delta_const invalid count"
+            errorf("push_delta_const invalid count %d %d %f %f %f %f %f %f %f %f"
-                    " %d %d %f %f %f %f %f %f %f %f\n"
+                   , sc->oid, count, clock_offset, dist, step_dist, start_pos
-                    , sc->oid, count, clock_offset, dist, step_dist, start_pos
+                   , closest_height2, height, movez_r, inv_velocity);
-                    , closest_height2, height, movez_r, inv_velocity);
         return 0;
     }
     check_expand(sc, step_dist > 0., count);
@@ -488,10 +487,9 @@ stepcompress_push_delta_accel(
                  - height - zdist) / step_dist + .5;
     if (count <= 0 || count > 1000000) {
         if (count)
-            fprintf(stderr, "ERROR: push_delta_accel invalid count"
+            errorf("push_delta_accel invalid count %d %d %f %f %f %f %f %f %f %f"
-                    " %d %d %f %f %f %f %f %f %f %f\n"
+                   , sc->oid, count, clock_offset, dist, step_dist, start_pos
-                    , sc->oid, count, clock_offset, dist, step_dist, start_pos
+                   , closest_height2, height, movez_r, accel_multiplier);
-                    , closest_height2, height, movez_r, accel_multiplier);
         return 0;
     }
     check_expand(sc, step_dist > 0., count);