Implement logging to a SHM ringbuffer

This feature is automatically enabled when running a debug version of i3.
The logfile will use 1% of your physical RAM size, but at max 25 MiB.

common.mk

@@ -68,6 +68,7 @@ CPPFLAGS += -DPCRE_HAS_UCP=1
 endif
 
 LIBS += -lm
+LIBS += -lrt
 LIBS += -L $(TOPDIR)/libi3 -li3
 LIBS += $(call ldflags_for_lib, xcb-event,xcb-event)
 LIBS += $(call ldflags_for_lib, xcb-keysyms,xcb-keysyms)

include/log.h

@@ -21,6 +21,8 @@
 
 extern char *loglevels[];
 extern char *errorfilename;
+extern char *shmlogname;
+extern int shmlog_size;
 
 /**
  * Initializes logging by creating an error logfile in /tmp (or
@@ -35,6 +37,13 @@ void init_logging();
  */
 void add_loglevel(const char *level);
 
+/**
+ * Returns the offsets for the next write and for the last wrap.
+ * Necessary to print the i3 SHM log in the correct order.
+ *
+ */
+void get_log_markers(int *offset_next_write, int *offset_last_wrap, int *size);
+
 /**
  * Set verbosity of i3. If verbose is set to true, informative messages will
  * be printed to stdout. If verbose is set to false, only errors will be

src/log.c

@@ -15,9 +15,14 @@
 #include <sys/time.h>
 #include <unistd.h>
 #include <fcntl.h>
+#include <sys/mman.h>
+#include <sys/stat.h>
+#include <errno.h>
 
 #include "util.h"
 #include "log.h"
+#include "i3.h"
+#include "libi3.h"
 
 /* loglevels.h is autogenerated at make time */
 #include "loglevels.h"
@@ -27,21 +32,79 @@ static bool verbose = false;
 static FILE *errorfile;
 char *errorfilename;
 
+/* SHM logging variables */
+
+/* The name for the SHM (/i3-log-%pid). Will end up on /dev/shm on most
+ * systems. Global so that we can clean up at exit. */
+char *shmlogname = "";
+/* Size limit for the SHM log, by default 25 MiB. Can be overwritten using the
+ * flag --shmlog-size. */
+int shmlog_size = 25 * 1024 * 1024;
+/* If enabled, logbuffer will point to a memory mapping of the i3 SHM log. */
+static char *logbuffer;
+/* A pointer (within logbuffer) where data will be written to next. */
+static char *logwalk;
+/* A pointer to the byte where we last wrapped. Necessary to not print the
+ * left-overs at the end of the ringbuffer. */
+static char *loglastwrap;
+/* Size (in bytes) of the i3 SHM log. */
+static int logbuffer_size;
+/* File descriptor for shm_open. */
+static int logbuffer_shm;
+
 /*
  * Initializes logging by creating an error logfile in /tmp (or
  * XDG_RUNTIME_DIR, see get_process_filename()).
  *
+ * Will be called twice if --shmlog-size is specified.
+ *
  */
 void init_logging() {
-    errorfilename = get_process_filename("errorlog");
+    if (!errorfilename) {
-    if (errorfilename == NULL) {
+        if (!(errorfilename = get_process_filename("errorlog")))
-        ELOG("Could not initialize errorlog\n");
+            ELOG("Could not initialize errorlog\n");
-        return;
+        else {
+            errorfile = fopen(errorfilename, "w");
+            if (fcntl(fileno(errorfile), F_SETFD, FD_CLOEXEC)) {
+                ELOG("Could not set close-on-exec flag\n");
+            }
+        }
     }
 
-    errorfile = fopen(errorfilename, "w");
+    /* If this is a debug build (not a release version), we will enable SHM
-    if (fcntl(fileno(errorfile), F_SETFD, FD_CLOEXEC)) {
+     * logging by default, unless the user turned it off explicitly. */
-        ELOG("Could not set close-on-exec flag\n");
+    if (logbuffer == NULL && shmlog_size > 0) {
+        /* Reserve 1% of the RAM for the logfile, but at max 25 MiB.
+         * For 512 MiB of RAM this will lead to a 5 MiB log buffer.
+         * At the moment (2011-12-10), no testcase leads to an i3 log
+         * of more than ~ 600 KiB. */
+        long long physical_mem_bytes = (long long)sysconf(_SC_PHYS_PAGES) *
+                                                  sysconf(_SC_PAGESIZE);
+        logbuffer_size = min(physical_mem_bytes * 0.01, shmlog_size);
+        sasprintf(&shmlogname, "/i3-log-%d", getpid());
+        logbuffer_shm = shm_open(shmlogname, O_RDWR | O_CREAT | O_TRUNC, S_IREAD | S_IWRITE);
+        if (logbuffer_shm == -1) {
+            ELOG("Could not shm_open SHM segment for the i3 log: %s\n", strerror(errno));
+            return;
+        }
+
+        if (ftruncate(logbuffer_shm, logbuffer_size) == -1) {
+            close(logbuffer_shm);
+            shm_unlink("/i3-log-");
+            ELOG("Could not ftruncate SHM segment for the i3 log: %s\n", strerror(errno));
+            return;
+        }
+
+        logbuffer = mmap(NULL, logbuffer_size, PROT_READ | PROT_WRITE, MAP_SHARED, logbuffer_shm, 0);
+        if (logbuffer == MAP_FAILED) {
+            close(logbuffer_shm);
+            shm_unlink("/i3-log-");
+            ELOG("Could not mmap SHM segment for the i3 log: %s\n", strerror(errno));
+            logbuffer = NULL;
+            return;
+        }
+        logwalk = logbuffer;
+        loglastwrap = logbuffer + logbuffer_size;
     }
 }
 
@@ -79,28 +142,78 @@ void add_loglevel(const char *level) {
 }
 
 /*
- * Logs the given message to stdout while prefixing the current time to it.
+ * Returns the offsets for the next write and for the last wrap.
+ * Necessary to print the i3 SHM log in the correct order.
+ *
+ */
+void get_log_markers(int *offset_next_write, int *offset_last_wrap, int *size) {
+    *offset_next_write = (logwalk - logbuffer);
+    *offset_last_wrap = (loglastwrap - logbuffer);
+    *size = logbuffer_size;
+}
+
+/*
+ * Logs the given message to stdout (if print is true) while prefixing the
+ * current time to it. Additionally, the message will be saved in the i3 SHM
+ * log if enabled.
  * This is to be called by *LOG() which includes filename/linenumber/function.
  *
  */
-void vlog(char *fmt, va_list args) {
+static void vlog(const bool print, const char *fmt, va_list args) {
-    static char timebuf[64];
+    /* Precisely one page to not consume too much memory but to hold enough
+     * data to be useful. */
+    static char message[4096];
     static struct tm result;
+    static time_t t;
+    static struct tm *tmp;
+    static size_t len;
 
     /* Get current time */
-    time_t t = time(NULL);
+    t = time(NULL);
     /* Convert time to local time (determined by the locale) */
-    struct tm *tmp = localtime_r(&t, &result);
+    tmp = localtime_r(&t, &result);
     /* Generate time prefix */
-    strftime(timebuf, sizeof(timebuf), "%x %X - ", tmp);
+    len = strftime(message, sizeof(message), "%x %X - ", tmp);
+
+    /*
+     * logbuffer  print
+     * ----------------
+     *  true      true   format message, save, print
+     *  true      false  format message, save
+     *  false     true   print message only
+     *  false     false  INVALID, never called
+     */
+    if (!logbuffer) {
 #ifdef DEBUG_TIMING
-    struct timeval tv;
+        struct timeval tv;
-    gettimeofday(&tv, NULL);
+        gettimeofday(&tv, NULL);
-    printf("%s%d.%d - ", timebuf, tv.tv_sec, tv.tv_usec);
+        printf("%s%d.%d - ", message, tv.tv_sec, tv.tv_usec);
 #else
-    printf("%s", timebuf);
+        printf("%s", message);
 #endif
-    vprintf(fmt, args);
+        vprintf(fmt, args);
+    } else {
+        len += vsnprintf(message + len, sizeof(message) - len, fmt, args);
+        if (len == sizeof(message)) {
+            fprintf(stderr, "BUG: single log message > 4k\n");
+        }
+        /* If there is no space for the current message (plus trailing
+         * nullbyte) in the ringbuffer, we need to wrap and write to the
+         * beginning again. */
+        if ((len+1) >= (logbuffer_size - (logwalk - logbuffer))) {
+            loglastwrap = logwalk;
+            logwalk = logbuffer;
+        }
+
+        /* Copy the buffer, terminate it, move the write pointer to the byte after
+         * our current message. */
+        strncpy(logwalk, message, len);
+        logwalk[len] = '\0';
+        logwalk += len + 1;
+
+        if (print)
+            fwrite(message, len, 1, stdout);
+    }
 }
 
 /*
@@ -111,11 +224,11 @@ void vlog(char *fmt, va_list args) {
 void verboselog(char *fmt, ...) {
     va_list args;
 
-    if (!verbose)
+    if (!logbuffer && !verbose)
         return;
 
     va_start(args, fmt);
-    vlog(fmt, args);
+    vlog(verbose, fmt, args);
     va_end(args);
 }
 
@@ -127,7 +240,7 @@ void errorlog(char *fmt, ...) {
     va_list args;
 
     va_start(args, fmt);
-    vlog(fmt, args);
+    vlog(true, fmt, args);
     va_end(args);
 
     /* also log to the error logfile, if opened */
@@ -146,10 +259,10 @@ void errorlog(char *fmt, ...) {
 void debuglog(uint64_t lev, char *fmt, ...) {
     va_list args;
 
-    if ((loglevel & lev) == 0)
+    if (!logbuffer && !(loglevel & lev))
         return;
 
     va_start(args, fmt);
-    vlog(fmt, args);
+    vlog((loglevel & lev), fmt, args);
     va_end(args);
 }