Merge branch 'logger-module-parts' into 'master'

Adding logger module to advligorts

See merge request !382

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/ -I$(mkfile_dir) 
+
+# 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_no_space = 0;
+atomic_t g_dump_to_dmesg = ATOMIC_INIT(1);
+
+
+
+//
+// Sysfs data
+//
+static ssize_t sysfs_no_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_no_space_dropped_attr = __ATTR(no_space_dropped, 0444, sysfs_no_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_no_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_no_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_no_space( void )
+{
+    return num_dropped_no_space;
+}
+EXPORT_SYMBOL(rtslog_get_num_dropped_no_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, which will be fast
+            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
+        // for a while
+        if( atomic_read(&g_num_filled) == 0)
+            usleep_range(1000, 2500);
+        else //We have more messages
+            schedule();
+    }
+    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_no_space_dropped(struct kobject *kobj, struct kobj_attribute *attr, char *buf)
+{
+    return sprintf(buf, "%d\n", num_dropped_no_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
+//
+
+/**
+ * @usage This is the main interface that should be used to log messages
+ *        from front end code infrastructure. The default log level is INFO,
+ *        so you must set the logger level to DEBUG before you will see debug
+ *        level messages. 
+ *
+ * These macros can be used just like prink or printf:
+ *
+ * RTSLOG_INFO("A string: %s and an int: %d\n", "Hello", 5);
+ *
+ */
+#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__)
+
+
+//
+// Debugging/Stats functions
+//
+
+/**
+* @brief Requests the new log level be set in the logger.
+* 
+* When the kernel module version is being used the sysfs interface
+* can be used to set this value. 
+*
+* cat /sys/kernel/rts_logger/debug_level
+*
+* @param new_level  The new log level to set (a RTSLOG_LOG_LEVEL)
+*
+* @return 1 if the log level was set, 0 if the log level was invalid        
+*/
+int rtslog_set_log_level(int new_level);
+
+/**
+* @brief Requests the new log level be set in the logger
+*
+* @return The level set (a RTSLOG_LOG_LEVEL)
+*/
+int rtslog_get_log_level( void );
+
+/**
+* @brief Requests number of messages that have been dropped
+*        due to a full buffer. This should't happen, but can
+*        if too many modules are spamming messages faster than
+*        they can be printed. This is an accumulative count 
+*        from module insertion (kernel space), or process creation (usermode)
+*
+* @return The number of messages that have been dropped 
+*/
+int rtslog_get_num_dropped_space ( void );
+
+/**
+* @brief Requests number of messages that are currently 
+*        queued, waiting for printing.
+*
+* @return The number of messages that are queued for print
+*/
+int rtslog_get_num_ready_to_print( void );
+
+
+
+
+
+
+
+
+
+
+
+//
+// Internal functions
+//
+
+/**
+* @brief Don't call this function directly, use the macros above
+*
+* Passes the message to the logger for logging
+*
+* @param level The log level of this message
+* @param fmt   The format string of the message
+* @param ...   Arguments for the format string
+*
+* @return none
+*/
+
+void rtslog_print(int level, const char * fmt, ...);
+
+
+#endif //LIGO_RTS_LOGGER_H_INCLUDED