Adding logger module to advligorts

src/drv/rts-logger/README.md

+# RTS Logger
+This is a kernel module that allows real time modules to log messages before AND after they are isolated on a core. It works by providing a print function exported by this module that other modules use to pass their messages for printing. Because this module is not CPU isolated it is free to pass those messages to the kernel message buffer. 
+
+# Example Use
+```c
+//At top of file, define the logging prefix (usually the module name) before logger include
+#define RTS_LOG_PREFIX "logger_test"
+#include "rts-logger.h"
+
+...
+
+//Log info message
+RTSLOG_INFO("There are %d DACs used by the model.\n", num_dacs);
+
+if(some_check < 2)
+{
+    RTSLOG_ERROR("There was a fatal issue!\n");
+    pLocalEpics->epicsOutput.fe_status = DAQ_INIT_ERROR;
+    wait_for_exit_signal();
+    atomic_set(&g_atom_has_exited, 1);
+}
+
+```
+
+### Output (dmesg) Would Look Like
+```
+[17764.891415] logger_test: INFO - There are 2 DACs used by the model.
+[17764.896527] logger_test: ERROR - There was a fatal issue!
+```
+
+### journalctl
+You can follow all kernel messages using the command:
+```
+sudo journalctl -t kernel -f
+```
+
+If you wanted to filter for the realtime module named `x1tst`, you can use `grep`
+```
+sudo journalctl -t kernel -f | grep x1tst
+```
+
+# Structure
+```
+include/    # Contains shared header file that other modules would use for logger declarations.
+module/     # Main logger module implementation.
+test/       # Test module that spams the logger from a couple of threads.
+userspace/  # Userspace implementation for the logger
+```
+

src/drv/rts-logger/module/Makefile

+mkfile_path := $(abspath $(lastword $(MAKEFILE_LIST)))
+mkfile_dir := $(dir $(mkfile_path))
+
+# obj-m specifie we're a kernel module.
+obj-m += rts-logger.o
+
+EXTRA_CFLAGS += -I$(mkfile_dir)/../../../include/
+
+# Set the path to the Kernel build utils.
+KBUILD=/lib/modules/$(shell uname -r)/build/
+ 
+default:
+	$(MAKE) -C $(KBUILD) M=$(PWD) modules
+
+clean:
+	$(MAKE) -C $(KBUILD) M=$(PWD) clean
+
+menuconfig:
+	$(MAKE) -C $(KBUILD) M=$(PWD) menuconfig

src/drv/rts-logger/module/rts-logger.c

+#include <linux/module.h>
+#include <linux/init.h>
+#include <linux/delay.h>
+#include <linux/kthread.h>  // for threads
+#include <linux/spinlock.h>
+#include <linux/fs.h>
+#include <linux/cdev.h>
+#include <linux/slab.h>
+#include <linux/llist.h>
+
+#include "drv/rts-logger.h"
+
+//  Define the module metadata.
+#define MODULE_NAME "rts_logger"
+MODULE_AUTHOR("Ezekiel Dohmen ezekiel.dohmen@caltech.edu");
+MODULE_LICENSE("Dual BSD/GPL");
+MODULE_DESCRIPTION("A logging kernel module for isolated real time LIGO kernel modules");
+MODULE_VERSION("0.1");
+
+//
+// Global options
+//
+#define MAX_MSG_TO_READ_AT_ONCE 1024
+#define MAX_SYSFS_NUM_IN_SZ 12 //Max sized string we will take as input from sysfs
+
+
+//
+// Start Module Parameters
+//
+int MP_DEFAULT_LOG_LEVEL = RTSLOG_LOG_LEVEL_INFO;
+module_param(MP_DEFAULT_LOG_LEVEL, int, S_IRUSR);
+
+//Will get set to MP_DEFAULT_LOG_LEVEL on init 
+//but can be reset with sysfs "debug_level"
+atomic_t g_log_level = ATOMIC_INIT(0);
+
+
+
+//
+// Input message buffer locking and stats
+//
+#define MAX_BUFFERED_MSG (1<<12) //(4096) This must be a power of 2, because we are using a fast mod below
+#define MAX_MSG_LENGTH 2048
+static char print_buffer[MAX_BUFFERED_MSG][MAX_MSG_LENGTH];
+volatile static bool ready_for_print[MAX_BUFFERED_MSG];
+
+static int cur_empty_index = 0;
+static int next_to_print = 0;
+atomic_t g_num_filled = ATOMIC_INIT(0); 
+spinlock_t g_check_and_dec_lock;
+
+static int num_dropped_space = 0;
+atomic_t g_dump_to_dmesg = ATOMIC_INIT(1);
+
+
+
+//
+// Sysfs data
+//
+static ssize_t sysfs_space_dropped(struct kobject *kobj, struct kobj_attribute *attr, char *buf);
+static ssize_t sysfs_dump_to_dmesg_show(struct kobject *kobj, struct kobj_attribute *attr, char *buf);
+static ssize_t sysfs_dump_to_dmesg_store(struct kobject *kobj, struct kobj_attribute *attr, const char *buf, size_t count);
+static ssize_t sysfs_debug_level_show(struct kobject *kobj, struct kobj_attribute *attr, char *buf);
+static ssize_t sysfs_debug_level_store(struct kobject *kobj, struct kobj_attribute *attr, const char *buf, size_t count);
+
+/* sysfs related structures */
+static struct kobject *g_sysfs_dir = NULL;
+
+/* individual sysfs debug attributes */
+static struct kobj_attribute sysfs_space_dropped_attr = __ATTR(space_dropped, 0444, sysfs_space_dropped, NULL);
+static struct kobj_attribute sysfs_dump_to_dmesg_attr = __ATTR(dump_to_dmesg, 0644, sysfs_dump_to_dmesg_show, sysfs_dump_to_dmesg_store);
+static struct kobj_attribute sysfs_debug_level_attr = __ATTR(debug_level, 0644, sysfs_debug_level_show, sysfs_debug_level_store);
+
+/* group attributes together for bulk operations */
+static struct attribute *g_sysfs_fields[] = {
+        &sysfs_space_dropped_attr.attr,
+        &sysfs_dump_to_dmesg_attr.attr,
+        &sysfs_debug_level_attr.attr,
+        NULL,
+};
+
+static struct attribute_group g_attr_group = {
+        .attrs = g_sysfs_fields,
+};
+
+
+
+//
+// Printer thread
+//
+static struct task_struct *printer_thread;
+static char thread_name[] = {"printer_thread"};
+
+void rtslog_print(int level, const char * fmt, ...)
+{
+    int  index;
+    va_list args;
+
+    if (level < atomic_read(&g_log_level) ) return;
+
+    va_start(args, fmt);
+
+
+    spin_lock(&g_check_and_dec_lock); //Lock so we can get our index
+
+    //If we are full return
+    if(atomic_read(&g_num_filled) == MAX_BUFFERED_MSG)
+    {
+        ++num_dropped_space;
+        spin_unlock(&g_check_and_dec_lock);
+        return;
+    }
+
+    index = cur_empty_index;
+    cur_empty_index = ((cur_empty_index + 1) & (MAX_BUFFERED_MSG - 1));
+    atomic_inc(&g_num_filled); //If we have two threads that mark ready, but have not finished writing to the print buffer we have an issue
+    spin_unlock(&g_check_and_dec_lock); //We unlock here
+
+    vsnprintf(print_buffer[index], MAX_MSG_LENGTH, fmt, args);
+    ready_for_print[index] = 1;
+
+    va_end(args);
+
+}
+EXPORT_SYMBOL(rtslog_print);
+
+int rtslog_get_num_dropped_space( void )
+{
+    return num_dropped_space;
+}
+EXPORT_SYMBOL(rtslog_get_num_dropped_space);
+
+int rtslog_get_num_ready_to_print( void)
+{
+    return atomic_read(&g_num_filled);
+}
+EXPORT_SYMBOL(rtslog_get_num_ready_to_print);
+
+int rtslog_set_log_level(int new_level)
+{
+    if(new_level < RTSLOG_LOG_LEVEL_DEBUG || new_level > RTSLOG_LOG_LEVEL_ERROR) return 0;
+
+    atomic_set(&g_log_level, new_level);
+    return 1;
+}
+EXPORT_SYMBOL(rtslog_set_log_level);
+
+int rtslog_get_log_level( void )
+{
+    return atomic_read(&g_log_level);
+}
+EXPORT_SYMBOL(rtslog_get_log_level);
+
+int printer_thread_fn( void * pv ) 
+{
+    int num_read = 0;
+    while(!kthread_should_stop()) {
+
+        while(!kthread_should_stop() && atomic_read(&g_num_filled) > 0 && num_read < MAX_MSG_TO_READ_AT_ONCE)
+        {
+
+            //If num filled is ready but ready_for_print is not, we are waiting for 
+            //the vsnprintf to complete
+            if(ready_for_print[next_to_print] == 0)
+            {
+                schedule();
+                num_read++;
+                continue;
+            }
+
+
+            if ( atomic_read(&g_dump_to_dmesg) )
+            {
+                printk("%s", print_buffer[next_to_print]);
+            }
+
+            ready_for_print[next_to_print] = 0;
+            next_to_print = ((next_to_print + 1) & (MAX_BUFFERED_MSG - 1));
+            atomic_dec(&g_num_filled);
+            num_read++;
+        }
+        num_read = 0;
+
+        //If there are no mesages ready for printing, we can give up the CPU
+        if( atomic_read(&g_num_filled) == 0)
+            usleep_range(499, 1000);
+    }
+    return 0;
+}
+
+
+static int __init logger_init(void)
+{
+
+    int ret;
+
+    // Set the default log level and other defaults
+    atomic_set(&g_log_level, (int)MP_DEFAULT_LOG_LEVEL);
+    spin_lock_init(&g_check_and_dec_lock);
+    memset((void*)ready_for_print, 0, sizeof(bool) * MAX_BUFFERED_MSG);
+
+
+    //
+    // Sysfs init
+    //
+    g_sysfs_dir = kobject_create_and_add("rts_logger", kernel_kobj);
+    if (g_sysfs_dir == NULL) {
+        printk(KERN_ERR " - " MODULE_NAME "Could not create /sys/kernel/rts_logger directory!\n");
+        return -EPERM;
+    }
+
+    if (sysfs_create_group(g_sysfs_dir, &g_attr_group) != 0) {
+        printk(KERN_ERR " - " MODULE_NAME "Could not create /sys/kernel/rts_logger/... fields!\n");
+        ret = -EPERM;
+        goto out_remove_sysfs;
+    }
+
+
+    //
+    // Start the printer kthread
+    printer_thread = kthread_run(printer_thread_fn, NULL, thread_name);
+    if( !printer_thread )
+    {
+        printk(KERN_ERR " - " MODULE_NAME " - Could not create the reader kthread.\n");
+        return -1;
+    }
+
+
+
+
+    printk(MODULE_NAME " - Successfully started the " MODULE_NAME " kernel module.\n");
+    return 0;
+
+
+    // error case cleanup
+    out_remove_sysfs:
+        kobject_del(g_sysfs_dir);
+
+    return ret;
+ 
+}
+
+static void __exit logger_exit(void)
+{
+    //Stop the printer thread
+    kthread_stop(printer_thread);
+
+    //Clean up sysfs
+    sysfs_remove_group(g_sysfs_dir, &g_attr_group);
+    kobject_del(g_sysfs_dir);
+
+    printk(MODULE_NAME " - Shutting down.\n");
+    return;
+}
+
+module_init(logger_init);
+module_exit(logger_exit);
+
+
+
+
+//
+// Sysfs related data/code
+//
+
+bool parseInt(const char *buf, size_t count, int * result, int * error_code)
+{
+    char localbuff[MAX_SYSFS_NUM_IN_SZ] = {0,};
+
+    if(count > MAX_SYSFS_NUM_IN_SZ)
+    {
+        *error_code = -E2BIG;
+        return false;
+    }
+
+    memcpy(localbuff, buf, count);
+    localbuff[count] = '\0';
+
+    if ((*error_code = kstrtoint(localbuff, 10, result)) != 0) {
+        return false ;
+    }
+
+    return true;
+
+}
+
+
+static ssize_t sysfs_space_dropped(struct kobject *kobj, struct kobj_attribute *attr, char *buf)
+{
+    return sprintf(buf, "%d\n", num_dropped_space);
+}
+
+static ssize_t sysfs_dump_to_dmesg_show(struct kobject *kobj, struct kobj_attribute *attr, char *buf)
+{
+    return sprintf(buf, "%d\n", atomic_read(&g_dump_to_dmesg) );
+}
+
+static ssize_t sysfs_dump_to_dmesg_store(struct kobject *kobj, struct kobj_attribute *attr, const char *buf, size_t count)
+{
+    int enabled, res;
+
+    if( !parseInt(buf, count, &enabled, &res) ) return res;
+
+    if(enabled >= 1) 
+        atomic_set(&g_dump_to_dmesg, 1); 
+    else
+        atomic_set(&g_dump_to_dmesg, 0);
+
+    return (ssize_t) count;
+}
+
+static ssize_t sysfs_debug_level_show(struct kobject *kobj, struct kobj_attribute *attr, char *buf)
+{
+    return sprintf(buf, "%d\n", atomic_read(&g_log_level));
+}
+
+static ssize_t sysfs_debug_level_store(struct kobject *kobj, struct kobj_attribute *attr, const char *buf, size_t count)
+{
+    int new_level, res;
+
+    if( !parseInt(buf, count, &new_level, &res) ) return res;
+
+    if(new_level < RTSLOG_LOG_LEVEL_DEBUG || new_level > RTSLOG_LOG_LEVEL_ERROR) return -EINVAL;
+
+    atomic_set(&g_log_level, new_level);
+
+    return (ssize_t) count;
+
+}
+
+
+
+
+
+
+
+
+

src/drv/rts-logger/test/Makefile

+mkfile_path := $(abspath $(lastword $(MAKEFILE_LIST)))
+mkfile_dir := $(dir $(mkfile_path))
+
+KBUILD_EXTRA_SYMBOLS += $(mkfile_dir)/../module/Module.symvers
+
+EXTRA_CFLAGS += -I$(mkfile_dir)/../../../include/
+
+# obj-m specifie we're a kernel module.
+obj-m += logger-test.o
+
+# Set the path to the Kernel build utils.
+KBUILD=/lib/modules/$(shell uname -r)/build/
+ 
+default:
+	$(MAKE) -C $(KBUILD) M=$(PWD) modules
+
+clean:
+	$(MAKE) -C $(KBUILD) M=$(PWD) clean
+
+menuconfig:
+	$(MAKE) -C $(KBUILD) M=$(PWD) menuconfig

src/drv/rts-logger/test/logger-test.c

+#include <linux/module.h>
+#include <linux/init.h>
+#include <linux/delay.h>
+#include <linux/kthread.h>  // for threads
+
+//  Define the module metadata.
+#define MODULE_NAME "logger_test"
+MODULE_AUTHOR("Ezekiel Dohmen ezekiel.dohmen@caltech.edu");
+MODULE_LICENSE("Dual BSD/GPL");
+MODULE_DESCRIPTION("A logging kernel module for isolated real time LIGO kernel modules");
+MODULE_VERSION("0.1");
+
+#define RTS_LOG_PREFIX MODULE_NAME
+#include "drv/rts-logger.h"
+
+int MP_JUST_QUERY_NUM_READY = 0;
+module_param(MP_JUST_QUERY_NUM_READY, int, S_IRUSR);
+
+
+static struct task_struct *g_thread;
+static char thread_name[] = {"test thread"};
+
+int thread_fn( void * pv ) 
+{
+    while(!kthread_should_stop()) {
+        
+         RTSLOG_INFO("Thread print.\n");
+         usleep_range(100, 500);
+
+        schedule();
+    }
+    return 0;
+}
+
+
+static int __init logger_init(void)
+{
+
+    if (MP_JUST_QUERY_NUM_READY == 1)
+    {
+         printk(MODULE_NAME " - rtslog_get_num_ready_to_print() : %d\n", rtslog_get_num_ready_to_print());
+         return -5;
+    }
+
+    
+    g_thread = kthread_run(thread_fn, NULL, thread_name);
+    if( !g_thread )
+    {
+        printk(KERN_ERR " - " MODULE_NAME " - Could not create the reader kthread.\n");
+        return -5;
+    }
+
+    int i;
+    for(i=0; i<500; ++i)
+    {
+        RTSLOG_INFO("test %d\n", i);
+        RTSLOG_DEBUG("we should not see this message\n");
+        usleep_range(100, 500);
+    }
+
+    printk(MODULE_NAME " - Successfully started the " MODULE_NAME " kernel module.\n");
+
+
+    return 0;
+}
+
+static void __exit logger_exit(void)
+{
+    kthread_stop(g_thread);
+
+    RTSLOG_RAW("RAW Test\n");
+    RTSLOG_RAW("RAW Test with arg (%s)\n", "arg");
+    RTSLOG_DEBUG("DEBUG Test\n");
+    RTSLOG_DEBUG("DEBUG Test with arg (%s)\n", "arg");
+    RTSLOG_INFO("INFO Test\n");
+    RTSLOG_INFO("INFO Test with arg (%s)\n", "arg");
+    RTSLOG_WARN("WARNING Test\n");
+    RTSLOG_WARN("WARNING Test with arg (%s)\n", "arg");
+    RTSLOG_ERROR("ERROR Test\n");
+    RTSLOG_ERROR("ERROR Test with arg (%s)\n", "arg");
+
+    usleep_range(10000, 10001);
+
+    printk(MODULE_NAME " - There were %d dropped messages because of space.\n", rtslog_get_num_dropped_space() );
+    printk(MODULE_NAME " - rtslog_get_num_ready_to_print() : %d\n", rtslog_get_num_ready_to_print());
+
+    printk(MODULE_NAME " - Shutting down.\n");
+    return;
+}
+
+module_init(logger_init);
+module_exit(logger_exit);

src/drv/rts-logger/userspace/usp-rts-logger.c

+#include "drv/rts-logger.h"
+
+#include <stdarg.h>
+#include <stdio.h>
+#include <stdatomic.h>
+
+atomic_int g_usp_rtslog_level = ATOMIC_VAR_INIT( RTSLOG_LOG_LEVEL_INFO );
+
+
+void rtslog_print(int level, const char * fmt, ...)
+{
+    va_list args;
+
+    if(level < g_usp_rtslog_level) return;
+
+    va_start(args, fmt);
+
+    vprintf(fmt, args);
+
+    va_end(args);
+
+}
+
+int rtslog_set_log_level(int new_level)
+{
+    if(new_level < RTSLOG_LOG_LEVEL_DEBUG || new_level > RTSLOG_LOG_LEVEL_ERROR) return 0;
+
+    atomic_store(&g_usp_rtslog_level, new_level);
+    return 1;
+
+}
+
+int rtslog_get_log_level( void )
+{
+    return atomic_load(&g_usp_rtslog_level);
+}
+
+
+int rtslog_get_num_dropped_space ( void )
+{
+    return 0;
+}
+
+int rtslog_get_num_ready_to_print( void )
+{
+    return 0;
+}
+

src/include/drv/rts-logger.h

+#ifndef LIGO_RTS_LOGGER_H_INCLUDED
+#define LIGO_RTS_LOGGER_H_INCLUDED
+/**
+ *  @section kernel_space
+ *  In kernel space the functions are exported by the rts-logger module.
+ *  Real-time kernel modules only need to copy their messages into the logger
+ *  module's buffer, and then can return to their work. The logger module does 
+ *  the interruptible work of calling prink, handling the high latancy/jittery 
+ *  portion of printing messages on a non-isolated core.
+ *
+ *  @section user_space
+ *  In user space these are defined in rts-logger/userspace/usp-rts-logger.c
+ *  We want to provide the same logging interface to user space that kernel space
+ *  gets, so we define these functions in user space. The user space implementation
+ *  is very simple, calling printf with the message. It is important to note that 
+ *  this implementation is slower than kernel space, because the user space version
+ *  actually calls printf in the model's thread.
+ *
+ */
+
+#ifndef RTS_LOG_PREFIX
+
+#if defined(FE_HEADER)
+#include FE_HEADER //SYSTEM_NAME_STRING_LOWER
+#define RTS_LOG_PREFIX SYSTEM_NAME_STRING_LOWER
+#endif
+
+#else
+#define RTS_LOG_PREFIX "undefined"
+#endif //ifndef RTS_LOG_PREFIX
+
+enum RTSLOG_LOG_LEVEL
+{
+    RTSLOG_LOG_LEVEL_DEBUG = 0,
+    RTSLOG_LOG_LEVEL_INFO = 1, //Default log level
+    RTSLOG_LOG_LEVEL_WARN = 2,
+    RTSLOG_LOG_LEVEL_ERROR = 3,
+    RTSLOG_LOG_LEVEL_RAW = 5
+};
+
+//
+// Start user functions
+//
+
+#define RTSLOG_RAW(fmt, ...) rtslog_print(RTSLOG_LOG_LEVEL_RAW, fmt, ##__VA_ARGS__)
+#define RTSLOG_DEBUG(fmt, ...) rtslog_print (RTSLOG_LOG_LEVEL_DEBUG, RTS_LOG_PREFIX ": DEBUG - " fmt, ##__VA_ARGS__)
+#define RTSLOG_INFO(fmt, ...) rtslog_print (RTSLOG_LOG_LEVEL_INFO, RTS_LOG_PREFIX ": INFO - " fmt, ##__VA_ARGS__)
+#define RTSLOG_WARN(fmt, ...) rtslog_print (RTSLOG_LOG_LEVEL_WARN, RTS_LOG_PREFIX ": WARN - " fmt, ##__VA_ARGS__)
+#define RTSLOG_ERROR(fmt, ...) rtslog_print (RTSLOG_LOG_LEVEL_ERROR, RTS_LOG_PREFIX ": ERROR - " fmt, ##__VA_ARGS__)
+
+int rtslog_set_log_level(int new_level);
+int rtslog_get_log_level( void );
+int rtslog_get_num_dropped_space ( void );
+int rtslog_get_num_ready_to_print( void );
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+//
+// Internal functions
+//
+void rtslog_print(int level, const char * fmt, ...);
+
+
+#endif